MySQL Bugs: #1684: "CORRUPT LOG RECORD FOUND" in error log after create tables with replicationl

Bug #1684	"CORRUPT LOG RECORD FOUND" in error log after create tables with replicationl
Submitted:	27 Oct 2003 22:56	Modified:	13 Nov 2003 9:02
Reporter:	[ name withheld ]	Email Updates:
Status:	Can't repeat	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S1 (Critical)
Version:	Ver 4.0.16-standard	OS:	Linux (Red Hat linux 7.3)
Assigned to:		CPU Architecture:	Any

Description:
Install above rpm version in Red hat Linux.

use the following to create a slave on the same machine
cp -LRp /var/lib/mysql /var/lib/mysql2  2>>/root/g24list >&2
rm -rf /var/lib/mysql2/it312-* 2>>/root/g24list >&2
rm -rf /var/lib/mysql2/hostname.pid* 2>>/root/g24list >&2 

replication working OK.

then create a few databases and about 30 tables of Innodb type.
all data replicated correctly.

restart master, the following appears on err log <host-name>-bin.err
031028 14:17:24  mysqld started
InnoDB: ############### CORRUPT LOG RECORD FOUND
InnoDB: Log record type 127, space id 4278452352, page number 1245750
InnoDB: Log parsing proceeded successfully up to 0 148249
InnoDB: Previous log record type 999999, is multi 0
InnoDB: Recv offset 0, prev 0
InnoDB: Hex dump of corrupt log starting 100 bytes before the start
InnoDB: of the previous log rec,
InnoDB: and ending 100 bytes after the start of the corrupt rec:
 len 200; hex 000000000000000000000000000000000000000000000000000000000000000000
00000000000000000000000000000000000000000000000000000000000000000000000000000000
00000000000000021020000870d745d0e57c0810002000f63d775fffffff040080d30236f0ffffff
ff040080d3023af0ffffffff040080d3023ef0ffffffff040080d30242f0ffffffff040080d30246
f0ffffffff040080d3024af0ffffffff040080d3024ef0ffffffff040080d30252f0ffffffff0400
80d30256f0ffff; asc ............................................................
...................... ..p.E..|... ..=w_........6..........:..........>.........
.B..........F..........J..........N..........R..........V...;
InnoDB: WARNING: the log file may have been corrupt and it
InnoDB: is possible that the log scan did not proceed
InnoDB: far enough in recovery! Please run CHECK TABLE
InnoDB: on your InnoDB tables to check that they are ok!
InnoDB: If mysqld crashes after this recovery, look at
InnoDB: section 6.1 of http://www.innodb.com/ibman.html
InnoDB: about forcing recovery.
031028 14:17:25  InnoDB: Error: page 11 log sequence number 0 148508
InnoDB: is in the future! Current system log sequence number 0 148249.
InnoDB: Your database may be corrupt.
031028 14:17:25  InnoDB: Error: page 5 log sequence number 0 148523
InnoDB: is in the future! Current system log sequence number 0 148249.
InnoDB: Your database may be corrupt.
031028 14:17:25  InnoDB: Error: page 45 log sequence number 0 148523
InnoDB: is in the future! Current system log sequence number 0 148249.
InnoDB: Your database may be corrupt.
031028 14:17:25  InnoDB: Error: page 0 log sequence number 0 148508
InnoDB: is in the future! Current system log sequence number 0 148249.
InnoDB: Your database may be corrupt.
InnoDB: WARNING: the log file may have been corrupt and it
InnoDB: is possible that the log scan or parsing did not proceed
InnoDB: far enough in recovery. Please run CHECK TABLE
InnoDB: on your InnoDB tables to check that they are ok!
InnoDB: It may be safest to recover your InnoDB database from
InnoDB: a backup!
031028 14:17:25  InnoDB: Started
/usr/sbin/mysqld: ready for connections.
Version: '4.0.16-standard-log'  socket: '/var/lib/mysql/mysql.sock'  port: 3306

mysqlcheck on the master and slave tables are OK.

repeat the same SQL commands without replication runs fine.

all scripts can be supplied if necessary.
Just email me and I can see you all the script files to repeat the error.

How to repeat:
as described above.

This does not look like Replication related at all.

"CORRUPT LOG RECORD FOUND" error as it says means InnoDB log file is corrupted somehow.

Make sure that are doing copy of datadir when mysqld is down. With running mysqld it is very likely to finish with corrupted files.

Please send more information if you can demonstrate how this corruption happens with fresh installed 4.0.16

output list with error

Attachment: controllist (text/plain), 8.84 KiB.

script to recreate the bug

Attachment: createbug (text/plain), 1.21 KiB.

control script that woudl not recreate the bug

Attachment: createbugcontrol (text/plain), 1.17 KiB.

output list with error for the bug

Attachment: createbuglist (text/plain), 12.43 KiB.

script to start master mysqld

Attachment: g20a (text/plain), 606 bytes.

script to start slave mysqld

Attachment: g20sa (text/plain), 550 bytes.

script to stop master mysqld

Attachment: g21a (text/plain), 365 bytes.

script to stop slave mysqld

Attachment: g21sa (text/plain), 549 bytes.

script to create /var/lib/mysql2 for slave mysqld

Attachment: g24a (text/plain), 841 bytes.

script to delete /var/lib/mysql for master mysqld

Attachment: g24ia (text/plain), 267 bytes.

script to view master mysqld's err file

Attachment: l2a (text/plain), 289 bytes.

script to get master mysqld's log record number for replication purpose

Attachment: m35a (text/plain), 170 bytes.

input for script m35a

Attachment: m35i (text/plain), 59 bytes.

script to start the replication process

Attachment: m36a (text/plain), 159 bytes.

input for script m36a

Attachment: m36i (text/plain), 202 bytes.

configuration file for master mysqld

Attachment: my.cnf (application/octet-stream, text), 3.19 KiB.

configuration file for slave mysqld

Attachment: my2.cnf (application/octet-stream, text), 3.67 KiB.

SQL commands for master mysqld to create the bug

Attachment: runsql (text/plain), 155 bytes.

input for script runsql

Attachment: runsqlinput (text/plain), 22.70 KiB.

I have attached the files for recreating the bug to this bug report.

Please reproduce the error on a linux red hat 7.3 PC with the following procedure and the attached files :

1.	Copy the attached my.cnf and my2.cnf into /etc
2.	Copy all the other attached files into /root
3.	stop mysqld with script g21a
4.	remove /var/lib/mysql with script g24ia
5.	use gnorpm to 
           - uninstall the 5 standard MySQL components
           - install the corresponding 5  4.0.16 rpm version of MySQL with
             the 3.28 compatile library
6.	run script /root/createbug to reproduce the “corrupt log record” bug

For control purpose, repeat steps 3 to 5, then run /root/createbugcontrol, which is exactly the same as /root/createbug but without starting the replicating process. This will not create the bug.

Hi!

I tested this with 4.0.17 with slightly modified my.cnf files. I have pasted them below. Note that I had to specify the datadir explicitly in them. Otherwise, they use the default datadir, and the test does not work.

No corruption was seen with the following procedure:

1. Create a fresh master installation.
2. Create a fresh slave installation.
3. Run the .sql script to the master.
4. Shut down the master.
5. Restart the master.

My guess is that somehow your servers use the SAME ib_logfiles as the InnoDB log. Then the second server corrupts the log, and when you restart the master, it prints the error message.

Please rerun the test so that you make absolutely sure that two mysqld servers are not writing to the same ib_logfiles or ibdata files, and they have distinct datadirs.

Regards,

Heikki

# Example mysql config file for medium systems.
#
# This is for a system with little memory (32M - 64M) where MySQL plays
# a important part and systems up to 128M very MySQL is used together with
# other programs (like a web server)
#
# You can copy this file to
# /etc/my.cnf to set global options,
# mysql-data-dir/my.cnf to set server-specific options (in this
# installation this directory is /usr/local/mysql/var) or
# /home/heikki/.my.cnf to set user-specific options.
#
# One can in this file use all long options that the program supports.
# If you want to know which options a program support, run the program
# with --help option.

# The following options will be passed to all MySQL clients
[client]
#password       = your_password
port            = 3307
socket          = /home/heikki/bugsocket2

# Here follows entries for some specific programs

# The MySQL server
[mysqld]
datadir         = /home/heikki/data
language        = /home/heikki/mysql-4.1/sql/share/english
port            = 3307
socket          = /home/heikki/bugsocket2
skip-locking
set-variable = max_connections=200
set-variable = record_buffer=1M
set-variable = sort_buffer=1M
set-variable    = key_buffer=16M
set-variable    = max_allowed_packet=1M
set-variable    = table_cache=64
set-variable    = sort_buffer=512K
set-variable    = net_buffer_length=8K
set-variable    = myisam_sort_buffer_size=8M
log-bin
server-id       = 35

# Point the following paths to different dedicated disks
tmpdir          = /tmp
#log-update     = /path-to-dedicated-directory/hostname

# Uncomment the following if you are using BDB tables
#set-variable   = bdb_cache_size=4M
#set-variable   = bdb_max_lock=10000

# Uncomment the following if you are using InnoDB tables
innodb_data_home_dir = /home/heikki/data
innodb_data_file_path = ibdata1:10M:autoextend
set-variable = innodb_mirrored_log_groups=1
innodb_log_group_home_dir = /home/heikki/data
innodb_log_arch_dir = /home/heikki/data
# You can set .._buffer_pool_size up to 50 - 80 %
# of RAM but beware of setting memory usage too high
set-variable = innodb_buffer_pool_size=70M
set-variable = innodb_additional_mem_pool_size=5M
set-variable = innodb_file_io_threads=4
# Set .._log_file_size to 25 % of buffer pool size
set-variable = innodb_log_file_size=20M
set-variable = innodb_log_buffer_size=8M
innodb_flush_log_at_trx_commit=1
set-variable = innodb_lock_wait_timeout=50
# InnoDB does a full purge and an insert buffer merge
# before a shutdown. May be slow hope to solve problem
set-variable = innodb_fast_shutdown=0

[mysqldump]
quick
set-variable    = max_allowed_packet=16M

[mysql]
no-auto-rehash
port            = 3307
socket          = /home/heikki/bugsocket2
# Remove the next comment character if you are not familiar with SQL
#safe-updates

[isamchk]
set-variable    = key_buffer=20M
set-variable    = sort_buffer=20M
set-variable    = read_buffer=2M
set-variable    = write_buffer=2M

[myisamchk]
set-variable    = key_buffer=20M
set-variable    = sort_buffer=20M
set-variable    = read_buffer=2M
set-variable    = write_buffer=2M

[mysqlhotcopy]
interactive-timeout

[mysqld_multi]
mysqld     = /usr/sbin/mysqld
mysqladmin = /usr/bin/mysqladmin
user       = root
password   = "bbbbbb"

[mysqld2]
socket     = /var/lib/mysql/mysql.sock2
port       = 3307
pid-file   = /var/lib/mysql/hostname.pid2
datadir    = /var/lib/mysql2/data2
language   = /usr/share/mysql/english
user       = root

....................................................

# Example mysql config file for medium systems.
#
# This is for a system with little memory (32M - 64M) where MySQL plays
# a important part and systems up to 128M very MySQL is used together with
# other programs (like a web server)
#
# You can copy this file to
# /etc/my.cnf to set global options,
# mysql-data-dir/my.cnf to set server-specific options (in this
# installation this directory is /usr/local/mysql/var) or
# /home/heikki/.my.cnf to set user-specific options.
#
# One can in this file use all long options that the program supports.
# If you want to know which options a program support, run the program
# with --help option.

# The following options will be passed to all MySQL clients
[client]
#password       = your_password
port            = 3308
socket          = /home/heikki/bugsocket

# Here follows entries for some specific programs

# The MySQL server
[mysqld]
server-id       = 135
master-host = hundin
master-port = 3307
master-user = slaveuser
master-password = slaveuser
report-host = hundin
slave-load-tmpdir = /tmp
datadir         = /home/heikki/data2
language        = /home/heikki/mysql-4.1/sql/share/english
port            = 3308
socket          = /home/heikki/bugsocket
skip-locking
set-variable    = key_buffer=16M
set-variable    = max_allowed_packet=1M
set-variable    = table_cache=64
set-variable    = sort_buffer=512K
set-variable    = net_buffer_length=8K
set-variable    = myisam_sort_buffer_size=8M
log-bin
log-warnings

# Point the following paths to different dedicated disks
tmpdir          = /tmp
#log-update     = /path-to-dedicated-directory/hostname

# Uncomment the following if you are using BDB tables
#set-variable   = bdb_cache_size=4M
#set-variable   = bdb_max_lock=10000

# Uncomment the following if you are using InnoDB tables
innodb_data_home_dir = /home/heikki/data2
innodb_data_file_path = ibdata1:10M:autoextend
set-variable = innodb_mirrored_log_groups=1
innodb_log_group_home_dir = /home/heikki/data2
innodb_log_arch_dir = /home/heikki/data2
# You can set .._buffer_pool_size up to 50 - 80 %
# of RAM but beware of setting memory usage too high
set-variable = innodb_buffer_pool_size=70M
set-variable = innodb_additional_mem_pool_size=5M
set-variable = innodb_file_io_threads=4
# Set .._log_file_size to 25 % of buffer pool size
set-variable = innodb_log_file_size=20M
set-variable = innodb_log_buffer_size=8M
innodb_flush_log_at_trx_commit=1
set-variable = innodb_lock_wait_timeout=50
# InnoDB does a full purge and an insert buffer merge
# before a shutdown. may be slow hope to solve probelm
set-variable = innodb_fast_shutdown=0

[mysqldump]
quick
set-variable    = max_allowed_packet=16M

[mysql]
no-auto-rehash
port            = 3308
socket          = /home/heikki/bugsocket
# Remove the next comment character if you are not familiar with SQL
#safe-updates

[isamchk]
set-variable    = key_buffer=20M
set-variable    = sort_buffer=20M
set-variable    = read_buffer=2M
set-variable    = write_buffer=2M

[myisamchk]
set-variable    = key_buffer=20M
set-variable    = sort_buffer=20M
set-variable    = read_buffer=2M
set-variable    = write_buffer=2M

[mysqlhotcopy]
interactive-timeout
[mysqld_multi]
mysqld     = /usr/sbin/mysqld
mysqladmin = /usr/bin/mysqladmin
user       = root
password   = "bbbbbb"

[mysqld2]
socket     = /var/lib/mysql2/mysql.sock2
port       = 3308
pid-file   = /var/lib/mysql2/hostname.pid2
datadir    = /var/lib/mysql2
language   = /usr/share/mysql/english
user       = root
port            = 3308
socket          = /var/lib/mysql2/mysql.sock2
skip-locking
set-variable    = key_buffer=16M
set-variable    = max_allowed_packet=1M
set-variable    = table_cache=64
set-variable    = sort_buffer=512K
set-variable    = net_buffer_length=8K
set-variable    = myisam_sort_buffer_size=8M
log-bin
server-id       = 135
log-warnings
# Do not replicate listed tables
# replicate-wild-ignore-table=Admin.Today%
replicate-wild-ignore-table=Scratch.%

heikki@hundin:~/mysql-4.0/sql> mysqld --defaults-file=~/mybug.cnf
InnoDB: The first specified data file /home/heikki/data/ibdata1 did not exist:
InnoDB: a new database to be created!
031113 18:48:04  InnoDB: Setting file /home/heikki/data/ibdata1 size to 10 MB
InnoDB: Database physically writes the file full: wait...
031113 18:48:05  InnoDB: Log file /home/heikki/data/ib_logfile0 did not exist: n
ew to be created
InnoDB: Setting log file /home/heikki/data/ib_logfile0 size to 20 MB
InnoDB: Database physically writes the file full: wait...
031113 18:48:09  InnoDB: Log file /home/heikki/data/ib_logfile1 did not exist: n
ew to be created
InnoDB: Setting log file /home/heikki/data/ib_logfile1 size to 20 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Doublewrite buffer not found: creating new
InnoDB: Doublewrite buffer created
InnoDB: Creating foreign key constraint system tables
InnoDB: Foreign key constraint system tables created
031113 18:48:13  InnoDB: Started
mysqld: ready for connections.
Version: '4.0.17-debug-log'  socket: '/home/heikki/bugsocket2'  port: 3307
031113 18:51:36  Got signal 15 to shutdown mysqld
031113 18:51:36  mysqld: Normal shutdown

031113 18:51:37  InnoDB: Starting shutdown...
031113 18:51:49  InnoDB: Shutdown completed
031113 18:51:49  mysqld: Shutdown Complete

heikki@hundin:~/mysql-4.0/sql> mysqld --defaults-file=~/mybug.cnf
031113 18:55:14  InnoDB: Started
mysqld: ready for connections.
Version: '4.0.17-debug-log'  socket: '/home/heikki/bugsocket2'  port: 3307

.....................

heikki@hundin:~/mysql-4.0/sql> mysqld --defaults-file=~/mybug2.cnf
InnoDB: The first specified data file /home/heikki/data2/ibdata1 did not exist:
InnoDB: a new database to be created!
031113 18:50:03  InnoDB: Setting file /home/heikki/data2/ibdata1 size to 10 MB
InnoDB: Database physically writes the file full: wait...
031113 18:50:04  InnoDB: Log file /home/heikki/data2/ib_logfile0 did not exist:
new to be created
InnoDB: Setting log file /home/heikki/data2/ib_logfile0 size to 20 MB
InnoDB: Database physically writes the file full: wait...
031113 18:50:05  InnoDB: Log file /home/heikki/data2/ib_logfile1 did not exist:
new to be created
InnoDB: Setting log file /home/heikki/data2/ib_logfile1 size to 20 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Doublewrite buffer not found: creating new
InnoDB: Doublewrite buffer created
InnoDB: Creating foreign key constraint system tables
InnoDB: Foreign key constraint system tables created
031113 18:50:08  InnoDB: Started
031113 18:50:08  Slave SQL thread initialized, starting replication in log 'FIRS
T' at position 0, relay log './hundin-relay-bin.001' position: 4
mysqld: ready for connections.
Version: '4.0.17-debug-log'  socket: '/home/heikki/bugsocket'  port: 3308
031113 18:50:08  Slave I/O thread: connected to master 'slaveuser@hundin:3307',
 replication started in log 'FIRST' at position 4
031113 18:51:36  Slave: received 0 length packet from server, apparent master sh
utdown:
031113 18:51:36  Slave I/O thread: Failed reading log event, reconnecting to ret
ry, log 'hundin-bin.001' position 23297
031113 18:51:36  Slave I/O thread: error reconnecting to master 'slaveuser@hundi
n:3307': Error: 'Lost connection to MySQL server during query'  errno: 2013  ret
ry-time: 60  retries: 86400
031113 18:55:36  Slave: connected to master 'slaveuser@hundin:3307',replication
resumed in log 'hundin-bin.001' at position 23297

Thank you for your effort in trying to solve the problem.
I have added the 'datadir' configuration statement into my.cnf and my2.cnf and repeated the uploaded scriptes and files. Unfortunately, the problem persists.
I think the problem is not just simply a mistaken-identity for a directory because without starting the replication process, no corruption occurs. Also, the environment if repeated in two different machine works fine, which is my planned productin environment. This master and slave in on machine is only for training and other minor purpose. So the priority for this problem is much lower than I first reported. As resources are tight world-wide, please don't spend efforts in solving it if resources are tight on your side.
However, it is still an interesting problem because I have spent a lot of time ont it without solving it.

Please pass my appreciation and thanks for your team.