MySQL Bugs: #68347: mysqlbinlog does not reset the "at" byte position counter with ROTATE

Bug #68347	mysqlbinlog does not reset the "at" byte position counter with ROTATE_EVENT
Submitted:	12 Feb 2013 4:45	Modified:	3 May 2013 13:36
Reporter:	Michael Ezzell	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Command-line Clients	Severity:	S3 (Non-critical)
Version:	5.6.10	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	mysqlbinlog

Description:
When using -R --stop-never --base64-output=decode-rows --verbose, mysqlbinlog fails to reset the "# at" position counter back to 0 when the binary log on the server is rotated, resulting in incorrect and ever-increasing values of the current byte position.

Using these options, in this example, when we reach the end of mysql-bin.001815 we successfully rotate to the next log, but the "# at [position]" values continue to increment (and also fails to include the bytes from the magic number and format description event).

/usr/local/mysql-5.6.10-linux-glibc2.5-x86_64/bin/mysqlbinlog Ver 3.3 for linux-glibc2.5 at x86_64

# at 1076476100
#130211 22:00:11 server id 10  end_log_pos 1076476127   Xid = 21171060
COMMIT/*!*/;
# at 1076476127
#130211 22:00:11 server id 11  end_log_pos 1076476170   Rotate to mysql-bin.001816  pos: 4
# at 1076476170
#691231 19:00:00 server id 11  end_log_pos 0    Rotate to mysql-bin.001816  pos: 4
# at 1076476170
#130211 22:00:11 server id 11  end_log_pos 107  Start: binlog v 4, server v 5.5.28-log created 130211 22:00:11
# at 1076476170
#130211 22:00:12 server id 10  end_log_pos 166  Query   thread_id=891630        exec_time=35    error_code=0
SET TIMESTAMP=1360638012/*!*/;
BEGIN
/*!*/;
# at 1076476229
#130211 22:00:12 server id 10  end_log_pos 332  Table_map: `xxxx`.`xxxx` mapped to number 230765
# at 1076476395
#130211 22:00:12 server id 10  end_log_pos 1042         Update_rows: table id 230765 flags: STMT_END_F

How to repeat:
Connect to a remote server with the 5.6.10 version of mysqlbinlog with -R --stop-never --base64-output=decode-rows --verbose and observe that the "# at [position]" value fails to reset, and instead continues to increment after the log rotates (but skips over the first event when counting).

Suggested fix:
Reset the counter when a ROTATE_EVENT is encountered and handled, so that the "# at [position]" messages agree with the prior end_log_pos value.

From the example above, with notes:

#691231 19:00:00 server id 11  end_log_pos 0    Rotate to mysql-bin.001816  pos: 4
# at 1076476170 << should be # at 0 or possibly # at 4 <<
#130211 22:00:11 server id 11  end_log_pos 107  Start: binlog v 4, server v 5.5.28-log created 130211 22:00:11
# at 1076476170 << should be # at 107 <<
#130211 22:00:12 server id 10  end_log_pos 166  Query   thread_id=891630        exec_time=35    error_code=0
SET TIMESTAMP=1360638012/*!*/;
BEGIN
/*!*/;
# at 1076476229 << should be # at 166 <<
#130211 22:00:12 server id 10  end_log_pos 332  Table_map: `xxxx`.`xxxx` mapped to number 230765
# at 1076476395 << should be # at 332 <<
#130211 22:00:12 server id 10  end_log_pos 1042         Update_rows: table id 230765 flags: STMT_END_F

verified as described

Thank you for your bug report. This issue has been committed to our source repository of that product and will be incorporated into the next release.

If necessary, you can access the source repository and build the latest available version, including the bug fix. More information about accessing the source trees is available at

    http://dev.mysql.com/doc/en/installing-source.html

Fixed in 5.6+. Documented in the 5.6.12 and 5.7.2 changelogs as follows:

        When using the options --read-from-remote-server --stop-never
        --base64-output=decode-rows --verbose, mysqlbinlog failed to reset the
        counter used to store the current position within the file when the
        binary log on the server was rotated.

Closed.