MySQL Bugs: #69568: mysqlbinlog --read-from-remote-server combined with --raw misses last operation

Bug #69568	mysqlbinlog --read-from-remote-server combined with --raw misses last operation
Submitted:	25 Jun 2013 8:52	Modified:	25 Jun 2013 10:06
Reporter:	Rik Vanachterberg	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: Command-line Clients	Severity:	S3 (Non-critical)
Version:	5.6	OS:	Linux (Debian Wheezy)
Assigned to:		CPU Architecture:	Any
Tags:	mysqlbinlog, raw

Description:
I am using 'mysqlbinlog' with flags '--stop-never', '--read-from-remote-server' and '--raw' to stream binlogs to a backup node, so we always have a backup with a very small window of data-loss in case of a total server outage. I have concluded that the 'mysqlbinlog' tool, used with the combination of flags '--read-from-remote-server' and '--raw' (advised for binlog backups) always fails to store the last operation runned on the MySQL server. This is however not the case when the '--raw' flag is not used. I'm supplying the relevant commands with output to reproduce this quirk. I'd be happy to supply more information if needed.

How to repeat:
## Examples shown on "mysqlserver" and "backupserver", both are installed with a fresh MySQL 5.5 server. Usernames and passwords are ommitted ##

backupserver# /opt/mysql/server-5.6/bin/mysqlbinlog -R -h mysqlserver --stop-never --raw mysql-bin.000001

mysqlserver# mysql -e 'create database example1;'
mysqlserver# mysql -e 'create database example2;'

backupserver# <after a few seconds, kill mysqlbinlog>
backupserver# /opt/mysql/server-5.6/bin/mysqlbinlog mysql-bin.000001 | grep 'create database example'
create database example1

## No "create database example2"! Let's try again without --raw. ##

backupserver# /opt/mysql/server-5.6/bin/mysqlbinlog -R -h mysqlserver --stop-never mysql-bin.000001
<snip>
SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=33/*!*/;
create database example1
/*!*/;
# at 47525
#130625  8:41:51 server id 1  end_log_pos 47616         Query   thread_id=51    exec_time=0     error_code=0
SET TIMESTAMP=1372149711/*!*/;
create database example2
/*!*/;
<snip>

Changed category from Server: Replication to Server: Command-line CLients

Hello Rik,

Thank you for the bug report.
Verified as described.

Thanks,
Umesh

// Master server

# bin/mysql -u root -p --port=3306 --protocol=TCP
Enter password: 
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.6.12-debug-log Source distribution

Copyright (c) 2000, 2013, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> create database ushastry1;
Query OK, 1 row affected (0.00 sec)

mysql> create database ushastry2;
Query OK, 1 row affected (0.00 sec)

mysql> create database ushastry3;
Query OK, 1 row affected (0.00 sec)

mysql> create database ushastry4;
Query OK, 1 row affected (0.01 sec)

mysql> show master logs;
+---------------------+-----------+
| Log_name            | File_size |
+---------------------+-----------+
| ushastry-bin.000001 |     69333 |
| ushastry-bin.000002 |       143 |
| ushastry-bin.000003 |       779 |
+---------------------+-----------+
3 rows in set (0.00 sec)

// confirming that event exists in the original binary log

mysql> SHOW BINLOG EVENTS IN 'ushastry-bin.000003' FROM 622;
+---------------------+-----+------------+-----------+-------------+-------------------------------------------------------------------+
| Log_name            | Pos | Event_type | Server_id | End_log_pos | Info                                                              |
+---------------------+-----+------------+-----------+-------------+-------------------------------------------------------------------+
| ushastry-bin.000003 | 622 | Gtid       |         1 |         670 | SET @@SESSION.GTID_NEXT= 'f38ba0a2-dd7a-11e2-a1c3-0800272e2cce:4' |
| ushastry-bin.000003 | 670 | Query      |         1 |         779 | create database ushastry4                                         |
+---------------------+-----+------------+-----------+-------------+-------------------------------------------------------------------+
2 rows in set (0.00 sec)

// Backup server

bin/mysqlbinlog -R -h myrepo -uroot --stop-never --raw ushastry-bin.000003

// Confirming that last event is indeed missing 

bin/mysqlbinlog ushastry-bin.000003 
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#130625 15:08:11 server id 1  end_log_pos 120 CRC32 0x679584a9 	Start: binlog v 4, server v 5.6.12-debug-log created 130625 15:08:11 at startup
ROLLBACK/*!*/;
BINLOG '
A2XJUQ8BAAAAdAAAAHgAAAAAAAQANS42LjEyLWRlYnVnLWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAADZclREzgNAAgAEgAEBAQEEgAAXAAEGggAAAAICAgCAAAACgoKGRkAAamE
lWc=
'/*!*/;
# at 120
#130625 15:08:11 server id 1  end_log_pos 151 CRC32 0x538501ac 	Previous-GTIDs
# [empty]
# at 151
#130625 15:13:31 server id 1  end_log_pos 199 CRC32 0x1efe77e5 	GTID [commit=yes]
SET @@SESSION.GTID_NEXT= 'f38ba0a2-dd7a-11e2-a1c3-0800272e2cce:1'/*!*/;
# at 199
#130625 15:13:31 server id 1  end_log_pos 308 CRC32 0xdac63dca 	Query	thread_id=1	exec_time=0	error_code=0
SET TIMESTAMP=1372153411/*!*/;
SET @@session.pseudo_thread_id=1/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1075838976/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=8/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
create database ushastry1
/*!*/;
# at 308
#130625 15:13:39 server id 1  end_log_pos 356 CRC32 0x2cb502c9 	GTID [commit=yes]
SET @@SESSION.GTID_NEXT= 'f38ba0a2-dd7a-11e2-a1c3-0800272e2cce:2'/*!*/;
# at 356
#130625 15:13:39 server id 1  end_log_pos 465 CRC32 0x6a11cea3 	Query	thread_id=1	exec_time=0	error_code=0
SET TIMESTAMP=1372153419/*!*/;
create database ushastry2
/*!*/;
# at 465
#130625 15:13:41 server id 1  end_log_pos 513 CRC32 0x65a2d935 	GTID [commit=yes]
SET @@SESSION.GTID_NEXT= 'f38ba0a2-dd7a-11e2-a1c3-0800272e2cce:3'/*!*/;
# at 513
#130625 15:13:41 server id 1  end_log_pos 622 CRC32 0xe66e9e39 	Query	thread_id=1	exec_time=0	error_code=0
SET TIMESTAMP=1372153421/*!*/;
create database ushastry3
/*!*/;
# at 622
#130625 15:16:27 server id 1  end_log_pos 670 CRC32 0xf2104f23 	GTID [commit=yes]
SET @@SESSION.GTID_NEXT= 'f38ba0a2-dd7a-11e2-a1c3-0800272e2cce:4'/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

// Without -raw

bin/mysqlbinlog -R -h myrepo -uroot --stop-never ushastry-bin.000003

<omitted>

# at 622
#130625 15:16:27 server id 1  end_log_pos 670 CRC32 0xf2104f23 	GTID [commit=yes]
SET @@SESSION.GTID_NEXT= 'f38ba0a2-dd7a-11e2-a1c3-0800272e2cce:4'/*!*/;
# at 670
#130625 15:16:27 server id 1  end_log_pos 779 CRC32 0xee2c2640 	Query	thread_id=1	exec_time=0	error_code=0
SET TIMESTAMP=1372153587/*!*/;
create database ushastry4
/*!*/;

I have find the reason for the problem.

mysqlbinlog using 'dump_remote_log_entries' to get remote master binlog events.
it will write log file in raw mode, but it use my_fwrite() which call fwrite() to write log event to the file. But do not call fflush() to flush the buffer.

as you know, fwrite() is a libc buffered write operation, so the last event does not write to the file (it still in the libc buffer). 

I have change fwrite() to write() system call,  last event does not lost.

HOW TO FIX:
not using fopen()/fwrite() to write the result_file, using open()/write() system call instead

what version has fix this bug on 5.6 or 5.7?