xtrabackup_binlog_pos_innodb provides a wrong position if no DML has been executed right after a DDL

[Jaime Sicam]

To test:

[user@sandbox msb_5_6_25]$ mysql --port=5625 test
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 3
Server version: 5.6.25-73.1-log Percona Server (GPL), Release 73.1, Revision 07b797f

Copyright (c) 2009-2015 Percona LLC and/or its affiliates
Copyright (c) 2000, 2015, 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 table t1(a int);
Query OK, 0 rows affected (0.08 sec)

mysql> insert into t1 values(1);
Query OK, 1 row affected (0.02 sec)

mysql> create table t2(a int);
Query OK, 0 rows affected (0.02 sec)

mysql> create table t3(a int);
Query OK, 0 rows affected (0.03 sec)

mysql> quit

Run and prepare backup:
[root@sandbox ~]# innobackupex --port=5625 --host=127.0.0.1 --user=root --password=msandbox --no-lock /backups

cd /backups/2015-08-11_01-46-44/
[root@sandbox ~]# innobackupex --apply-log .

Compare xtrabackup_binlog_pos_innodb and xtrabackup_binlog_info
[root@sandbox 2015-08-11_01-46-44]# cat xtrabackup_binlog_pos_innodb
mysql-bin.000001 424
[root@sandbox 2015-08-11_01-46-44]# cat xtrabackup_binlog_info
mysql-bin.000001 616

Binary log info:
[root@sandbox 2015-08-11_01-46-44]# mysqlbinlog /home/user/sandboxes/msb_5_6_25/data/mysql-bin.000001
/*!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
#150811 1:45:09 server id 1 end_log_pos 120 CRC32 0x9900a135 Start: binlog v 4, server v 5.6.25-73.1-log created 150811 1:45:09 at startup
# Warning: this binlog is either in use or was not closed properly.
ROLLBACK/*!*/;
BINLOG '
JePIVQ8BAAAAdAAAAHgAAAABAAQANS42LjI1LTczLjEtbG9nAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAl48hVEzgNAAgAEgAEBAQEEgAAXAAEGggAAAAICAgCAAAACgoKGRkAATWh
AJk=
'/*!*/;
# at 120
#150811 1:45:54 server id 1 end_log_pos 216 CRC32 0x2a7564f6 Query thread_id=3 exec_time=0 error_code=0
use `test`/*!*/;
SET TIMESTAMP=1439228754/*!*/;
SET @@session.pseudo_thread_id=3/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1073741824/*!*/;
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 table t1(a int)
/*!*/;
# at 216
#150811 1:46:01 server id 1 end_log_pos 295 CRC32 0x3cba96f4 Query thread_id=3 exec_time=0 error_code=0
SET TIMESTAMP=1439228761/*!*/;
BEGIN
/*!*/;
# at 295
#150811 1:46:01 server id 1 end_log_pos 393 CRC32 0xcf8e1536 Query thread_id=3 exec_time=0 error_code=0
SET TIMESTAMP=1439228761/*!*/;
insert into t1 values(1)
/*!*/;
# at 393
#150811 1:46:01 server id 1 end_log_pos 424 CRC32 0x19927c7b Xid = 11
COMMIT/*!*/;
# at 424
#150811 1:46:06 server id 1 end_log_pos 520 CRC32 0xfa1830ef Query thread_id=3 exec_time=0 error_code=0
SET TIMESTAMP=1439228766/*!*/;
create table t2(a int)
/*!*/;
# at 520
#150811 1:46:09 server id 1 end_log_pos 616 CRC32 0xf2f7dce9 Query thread_id=3 exec_time=0 error_code=0
SET TIMESTAMP=1439228769/*!*/;
create table t3(a int)
/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

The consequence of using coordinates from xtrabackup_binlog_pos_innodb is that it will report a "'Table 't2' already exists' on query" error when you setup replication.

[Nilnandan Joshi (nilnandan-joshi)]

Verified with PS 5.6 and Xtrabackup 2.2.12.

nilnandan@desktop:~$ mysql -uroot -p
Enter password:
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 75
Server version: 5.6.25-73.1-log Percona Server (GPL), Release 73.1, Revision 07b797f

Copyright (c) 2009-2015 Percona LLC and/or its affiliates
Copyright (c) 2000, 2015, 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>
mysql> create table t1(a int);
Query OK, 0 rows affected (0.00 sec)

mysql> insert into t1 values(1);
Query OK, 1 row affected (0.00 sec)

mysql> create table t2(a int);
'Query OK, 0 rows affected (0.02 sec)

mysql> create table t3(a int);
Query OK, 0 rows affected (0.01 sec)

mysql> quit
Bye
nilnandan@desktop:~$

Took and prepare the backup.

root@desktop:/home/nilnandan/backup/2015-08-11_11-58-04# cat xtrabackup_binlog_info
mysql-bin.000040 616
root@desktop:/home/nilnandan/backup/2015-08-11_11-58-04# cat xtrabackup_binlog_pos_innodb
mysql-bin.000040 424
root@desktop:/home/nilnandan/backup/2015-08-11_11-58-04#

root@desktop:/var/lib/mysql# mysqlbinlog mysql-bin.000040
/*!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
#150811 11:57:05 server id 1 end_log_pos 120 CRC32 0x56591a83 Start: binlog v 4, server v 5.6.25-73.1-log created 150811 11:57:05
# Warning: this binlog is either in use or was not closed properly.
BINLOG '
uZXJVQ8BAAAAdAAAAHgAAAABAAQANS42LjI1LTczLjEtbG9nAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAXAAEGggAAAAICAgCAAAACgoKGRkAAYMa
WVY=
'/*!*/;
# at 120
#150811 11:57:24 server id 1 end_log_pos 216 CRC32 0x2b22d4a6 Query thread_id=75 exec_time=0 error_code=0
use `test`/*!*/;
SET TIMESTAMP=1439274444/*!*/;
SET @@session.pseudo_thread_id=75/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1073741824/*!*/;
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 table t1(a int)
/*!*/;
# at 216
#150811 11:57:28 server id 1 end_log_pos 295 CRC32 0x06be9ec9 Query thread_id=75 exec_time=0 error_code=0
SET TIMESTAMP=1439274448/*!*/;
BEGIN
/*!*/;
# at 295
#150811 11:57:28 server id 1 end_log_pos 393 CRC32 0xac91be1b Query thread_id=75 exec_time=0 error_code=0
SET TIMESTAMP=1439274448/*!*/;
insert into t1 values(1)
/*!*/;
# at 393
#150811 11:57:28 server id 1 end_log_pos 424 CRC32 0x9b920b8b Xid = 238
COMMIT/*!*/;
# at 424
#150811 11:57:31 server id 1 end_log_pos 520 CRC32 0x11b2d0bd Query thread_id=75 exec_time=0 error_code=0
SET TIMESTAMP=1439274451/*!*/;
create table t2(a int)
/*!*/;
# ...

[Sergei Glushchenko (sergei.glushchenko)]

xtrabackup_binlog_pos_innodb is just a binary log position stored by InnoDB engine. In order to make it consistent we need to fix server. We did it for Percona Server, please check recent PS 5.6 and 5.7. It is described here: https://blueprints.launchpad.net/percona-server/+spec/backup-safe-binlog-info. I can easily reproduce the issue with upstream server, but recent PS 5.6 works OK.

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PXB-1341