MySQL Bugs: #78898: mysqlbackup does not store binlog pos in log file

Bug #78898	mysqlbackup does not store binlog pos in log file
Submitted:	21 Oct 2015 13:04	Modified:	22 Oct 2015 13:23
Reporter:	Oli Sennhauser	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Enterprise Backup	Severity:	S2 (Serious)
Version:	3.12.1	OS:	SUSE (SLE 11 SP3)
Assigned to:		CPU Architecture:	Any
Tags:	binlog, log file, mysqlbackup, position

Description:
mysqlbackup does not store binlog pos in log file

How to repeat:
v3.8

mysqlbackup: INFO: Last MySQL binlog file position 0 17291993, file name mesbinlog.000023

v3.12.1

mysqlbackup: INFO: Last MySQL binlog file position 0 18446744073709551615, file name mesbinlog.000023:-1

Seems to be an overflow or something similar.

Suggested fix:
MySQL should store binary log pos in a file like xtrabackup does.

Hi Oli,

Thank you for the report.
Imho MEB logs these information in couple of places i.e MEB log file, backup_history table.

// Sample backup

[umshastr@hod03]/export/umesh/utils/meb-3.12.1: bin/mysqlbackup --user=root --socket=/tmp/mysql_ushastry.sock  --backup-dir=/export/umesh/server/binaries/mysql-advanced-5.6.28/backups/backup-tmp  --with-timestamp backup
MySQL Enterprise Backup version 3.12.1 Linux-2.6.18-194.el5-x86_64 [2015/06/26]
Copyright (c) 2003, 2015, Oracle and/or its affiliates. All Rights Reserved.

.
.
151022 13:11:26 mysqlbackup: INFO: Backup created in directory '/export/umesh/server/binaries/mysql-advanced-5.6.28/backups/backup-tmp/2015-10-22_13-11-20'
151022 13:11:26 mysqlbackup: INFO: MySQL binlog position: filename master-bin.000001, position 1056 <-------------

-------------------------------------------------------------
   Parameters Summary
-------------------------------------------------------------
   Start LSN                  : 1625600
   End LSN                    : 1625997
-------------------------------------------------------------

mysqlbackup completed OK!
[umshastr@hod03]/export/umesh/utils/meb-3.12.1:

// from mysql.backup_history

mysql> select * from mysql.backup_history\G
*************************** 1. row ***************************
                backup_id: 14455122800626629
                tool_name: bin/mysqlbackup --user=root --socket=/tmp/mysql_ushastry.sock --backup-dir=/export/umesh/server/binaries/mysql-advanced-5.6.28/backups/backup-tmp --with-timestamp backup
               start_time: 2015-10-22 13:11:20
                 end_time: 2015-10-22 13:11:26
               binlog_pos: 1056              <-------------
              binlog_file: master-bin.000001 <-------------
        compression_level: 0
                  engines: MEMORY:MyISAM:CSV:InnoDB:PERFORMANCE_SCHEMA:
    innodb_data_file_path: ibdata1:12M:autoextend
       innodb_file_format: Antelope
                start_lsn: 1625600
                  end_lsn: 1625997
     incremental_base_lsn: 0
              backup_type: FULL
            backup_format: DIRECTORY
           mysql_data_dir: /export/umesh/server/binaries/mysql-advanced-5.6.28/78898/
     innodb_data_home_dir:
innodb_log_group_home_dir: /export/umesh/server/binaries/mysql-advanced-5.6.28/78898/
innodb_log_files_in_group: 2
     innodb_log_file_size: 50331648
       backup_destination: /export/umesh/server/binaries/mysql-advanced-5.6.28/backups/backup-tmp/2015-10-22_13-11-20
                lock_time: 2.983
               exit_state: SUCCESS
               last_error: NO_ERROR
          last_error_code: 0
1 row in set (0.00 sec)

// from log file

[umshastr@hod03]/export/umesh/utils/meb-3.12.1: tail -f /export/umesh/server/binaries/mysql-advanced-5.6.28/backups/backup-tmp/2015-10-22_13-11-20/meta/MEB_2015-10-22.13-11-20_backup.log
151022 13:11:26 mysqlbackup: INFO: MySQL binlog position: filename master-bin.000001, position 1056 <-------------

-------------------------------------------------------------
   Parameters Summary
-------------------------------------------------------------
   Start LSN                  : 1625600
   End LSN                    : 1625997
-------------------------------------------------------------

mysqlbackup completed OK!

Thanks,
Umesh

Dear Umesh

did you look and understand my example or does it need any further explanation?

Regards,
Oli

Dear Oli,

Sorry, looks like I overlooked your example and continued with synopsis i.e . "mysqlbackup does not store binlog pos in log file"..

v3.8

mysqlbackup: INFO: Last MySQL binlog file position 0 17291993, file name mesbinlog.000023

v3.12.1

mysqlbackup: INFO: Last MySQL binlog file position 0 18446744073709551615, file name mesbinlog.000023:-1

So, is that overflow "mesbinlog.000023:-1" issue here? Please could you explain it so that I would  check with dev's on this.

Thanks,
Umesh

Thanks Oli for the feedback.
Just confirmed that it is duplicate of internally logged bug Bug 21822086 - BINLOG FILE AND POSITIONS ARE NOT UPDATED CORRECTLY IN INCREMENTAL BACKUP LOG 

Thanks,
Umesh

Great thanks!

Just a little detail: Storing it in mysql.backup_history does not help because this table is gone when I need it...

So the solution is to store it in an easily machine and human parseble file (no, not XML, easy and lightweight!) for example in the meta-data directory.

I do not want to write another job after the backup to pick the binary log position out of the repository...

Posted by developer:
 
Added the following entry to the MySQL Enterprise Backup 3.12.4 and 3.13.0 changelog:

"After an apply-incremental-backup operation on a full backup, mysqlbackup printed to the output stream and the message log file the old instead of the updated binary log position."