Bug #71400 Binary log repeatedly corrupt on master - replication fails with error 1236
Submitted: 16 Jan 2014 15:10 Modified: 31 Jan 2014 14:56
Reporter: Martin Kirchner Email Updates:
Status: Closed Impact on me:
Category:MySQL Server: Replication Severity:S1 (Critical)
Version:5.6.15 OS:Linux (Debian 7.1)
Assigned to: CPU Architecture:Any

[16 Jan 2014 15:10] Martin Kirchner
Our customer has a replication ring of three nodes (two virtual machines and one physical machine): pia-db1-3. pia-db1 is master of pia-db2 which is master of pia-db3 which is master of pia-db2. Only one of the servers is the active master, i.e. all connections of any application are directed to this single server. No manual or automatic switch of the master happended between setup and break of the replication. At the moment pia-db3 is the active master.
Replication setup is done using GTID and consistency checks (see my.cnf below).

Every other day (about two/three times a week) replication breaks. No log output on the master, neither in Debian's syslog nor in MySQL's error log. The MySQL error log on the slave lists the following errors (pia-db1 in this case, master was pia-db3):
2014-01-16 04:40:53 12758 [ERROR] Error reading packet from server: binlog truncated in the middle of event; consider out of disk space on master; the first event '' at 4, the last event read from '/piasql/pia-db3-bin.000001' at 126098235, the last byte read from '/piasql/pia-db3-bin.000001' at 126098254. ( server_errno=1236)
2014-01-16 04:40:53 12758 [ERROR] Slave I/O: Got fatal error 1236 from master when reading data from binary log: 'binlog truncated in the middle of event; consider out of disk space on master; the first event '' at 4, the last event read from '/piasql/pia-db3-bin.000001' at 126098235, the last byte read from '/piasql/pia-db3-bin.000001' at 126098254.', Error_code: 1236
2014-01-16 04:40:53 12758 [Note] Slave I/O thread exiting, read up to log 'pia-db3-bin.000001', position 126098235
2014-01-16 04:40:53 12758 [ERROR] Slave SQL: Could not execute Delete_rows event on table svg.activesyncstaterel; Can't find record in 'activesyncstaterel', Error_code: 1032; handler error HA_ERR_KEY_NOT_FOUND; the event's master log pia-db3-bin.000001, end_log_pos 126073836, Error_code: 1032
2014-01-16 04:40:53 12758 [Warning] Slave: Can't find record in 'activesyncstaterel' Error_code: 1032
2014-01-16 04:40:53 12758 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'pia-db3-bin.000001' position 126065513

The binary log entries before/at/after the corrupt bin log position are quite often related to the table 'activesyncstaterel'. The transactions on this table can be quite big (some hundred inserts and deletes).

If I execute 
root@pia-db3:/piasql# mysqlbinlog pia-db3-bin.000001 > pia-db3-bin.000001_txt
on the master I get the following error:
ERROR: Error in Log_event::read_log_event(): 'read error', data_len: 276827242, event_type: 57
WARNING: The range of printed events ends with a row event or a table map event that does not have the STMT_END_F flag set. This might be because the last statement was not fully written to the log, or because you are using a --stop-position or --stop-datetime that refers to an event in the middle of a statement. The event(s) from the partial statement have not been written to output.

To me it seems that the binary log is corrupt.

I already switched the master to sort out hardware or I/O related issues. Same scenario on any of the three virtual or physical machines.

Replication relevant part of my.cnf (from pia-db3, same on the other machines):
# Replikation
server-id               = 12
log_bin                 = /piasql/pia-db3-bin.log
binlog-format   = MIXED
expire_logs_days        = 30
max_binlog_size     = 512M

How to repeat:
- Setup replication 
   -I use Percona xtrabackup to transfer a consistent dump from one machine to another
  - SET GLOBAL gtid_purged='...'; (as listed in xtrabackup_slave_info)
  - change master to master_host='pia-db3', master_user='repli', master_password='secret', master_auto_position=1;

- Replication starts and works for some hours or even a couple of days
- The application executes SQL statements on the active master.

After some days or hours replication breaks with the errors listed above (yesterday approx. 18 hours).
[16 Jan 2014 17:39] Sveta Smirnova
Thank you for the report.

Have you checked disk space as was suggested in the error message? Have you checked disk space, dedicated for MySQL tmpdir? If you use huge transactions and queries which process a lot of data you can fill up temporary space. Please double-check and update the report.
[16 Jan 2014 19:11] Martin Kirchner
Thanks for your answer.

On the virtual machines (pia-db1/2) the disk levels (df -h) are something like this:
Filesystem                                                Size Used Free Use% Mount point
rootfs                                                   40G    4,4G   33G   12% /
udev                                                     10M       0   10M    0% /dev
tmpfs                                                   3,2G    240K  3,2G    1% /run
/dev/disk/by-uuid/2133fe96-a39b-4dd6-b7e4-364af99f5eba   40G    4,4G   33G   12% /
tmpfs                                                   5,0M       0  5,0M    0% /run/lock
tmpfs                                                   6,3G     23M  6,3G    1% /run/shm
/dev/sdb1                                               443G    147G  275G   35% /piasql
//                                      1,8T    782G  1,1T   43% /mnt/backup

On pia-db3 (physical machine and active master):
Filesystem                                                Size Used Free Use% Mount point
rootfs                                                  130G    2,4G  121G    2% /
udev                                                     10M       0   10M    0% /dev
tmpfs                                                   3,2G    292K  3,2G    1% /run
/dev/disk/by-uuid/1a829d2f-921d-4d46-8dfc-450e4d80d1c1  130G    2,4G  121G    2% /
tmpfs                                                   5,0M       0  5,0M    0% /run/lock
tmpfs                                                    11G     23M   11G    1% /run/shm
/dev/cciss/c0d1p1                                       388G    292G   77G   80% /piasql
//                                      1,8T    782G  1,1T   43% /mnt/backup

/piasql is the MySQL data partition. / and /piasql are under constant monitoring via Nagios/check_mk and did not raise any alarm, the diagrams do not show any peeks that differ significantly from the values listed above.

MySQL uses /tmp as temp folder which seems to be a subfolder of /.

kirchner@localhost [(none)]>show global variables like '%tmp%';
| Variable_name              | Value      |
| default_tmp_storage_engine | InnoDB     |
| max_tmp_tables             | 32         |
| slave_load_tmpdir          | /tmp       |
| tmp_table_size             | 1073741824 |
| tmpdir                     | /tmp       |
5 rows in set (0,00 sec)

Thank you in advance for any help.
[18 Jan 2014 8:08] MySQL Verification Team
Hi Martin, I think we'll have to recommend you to wait for 5.6.16.  It should contain a fix for this:

Release (non-debug) build ends up with corrupted binlog, and debug build asserts.
[20 Jan 2014 10:23] Martin Kirchner
Hi Shane,

is there a roadmap when MySQL 5.6.16 will be available?
Is there a workaround to the internal bug you mentioned?
Can you give me some more information on that bug?

Thanks a lot.


[31 Jan 2014 14:56] MySQL Verification Team
5.6.16 is out during next month.
[28 Dec 2016 19:52] Arthur Burkart
Hi, I know this thread is long dead, but were there any steps for reproduction related to this issue? I'm trying to figure out if my release (10.1.20) of MariaDB is also impacted by this bug.

[28 Dec 2016 21:36] MySQL Verification Team
On the topic of testcases,  I did once make a psuedo-random one.  you could try it in a test setup.

How to repeat:
Start server like this:
--log-bin --log-slave-updates
--binlog-format=row --binlog-checksum=CRC32 --enforce-gtid-consistency=true
--gtid-mode=on --server-id=21 --binlog-rows-query-log-events=1

Setup testcase:
reset master;
set global sync_binlog=0;
set global lock_wait_timeout=1;
set global innodb_lock_wait_timeout=1;
set global innodb_flush_log_at_trx_commit=0;
drop table if exists t1;
create table t1(id tinyint unsigned primary key,a longblob)engine=innodb;

delimiter $
drop procedure if exists p1 $
create procedure p1()
  declare continue handler for sqlexception begin end;
    set @sql:=concat('replace into t1 set
id=floor(rand()*255),a="',repeat(char(rand()*255),cast(rand()*100000 as
    #select @sql;
    prepare stmt from @sql;
    execute stmt;
    set global max_binlog_size=cast(1024*100 + rand()*1024*1024 as unsigned);
    delete from t1 where id=cast(floor(rand()*255) as unsigned);
    if rand()*1000 > 998 then flush logs; end if;
  until 1=2 end repeat;
end $
delimiter ;

call p1(); #Run this in ~3 threads.

Launch a slave to read from the master. Here is a shortcut, just launch
this command to read your binlogs:

mysqlbinlog --read-from-remote-server -uroot --stop-never test-bin.000001
--to-last-log --base64-output=decode-rows -vvvv --verify-binlog-checksum  >
/dev/null &

Wait some minutes.
[30 Dec 2016 3:37] Arthur Burkart

Thanks so much for the repro steps. After spending way more time than I'd care to admit setting up a pair of mysql servers to test with, I was able to successfully reproduce the issue in 5.6.15. I was also unable to repro the issue in MariaDB 10.1.20.

I very much appreciate your help!