Mysqlbinlog not updating database for PITR

emaN_yalpsiD · July 17, 2025, 2:55pm

I’m running Percona MySQL 8.0.42-33 on RHEL 9.6.

I have a problem when attempting point-in-time-recovery, where I can restore the database from the mysqldump backup, but the application of the binlog isn’t updating anything in the database. There are no errors, and verbose output shows the statements being executed, but there are no changes in the database.

At first I thought this could be specific to the database I was attempting to restore, but running similar tests in our sandbox instance produced the same result. This is using a replica server that has replication stopped, and I reset the replica and master data before starting this process if that makes any difference.

Example Steps

create database test03
mysqldump --all-databases --log-error BACKUP_LOG --max-allowed-packet=1G --single-transaction --verbose --flush-logs --source-data=2 | gzip > BACKUP_DIR/BACKUP_FILE
CREATE TABLE Persons ( PersonID int, LastName varchar(255), FirstName varchar(255), Address varchar(255), City varchar(255) );
drop database test03
mysql < BACKUP_DIR/BACKUP_FILE
mysqlbinlog -vv log_bin.000002 --start-position=197 --stop-position=518 | mysql -v
use test03
show tables - Empty set (0.00 sec)

In this case the test03 database is restored from backup, but the Persons table is not added when processing the binlog. I’ve verified that I’m not read-only or anything like that, and I can see the transaction in the binlog:

#250717 9:32:22 server id 5 end_log_pos 518 CRC32 0x798e87b9 Query thread_id=125856 exec_time=0 error_code=0 Xid = 112497 use test03/*!*/; SET TIMESTAMP=1752759142/*!*/; SET @@session.pseudo_thread_id=125856/*!*/; SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/; SET @@session.sql_mode=1168113696/*!*/; SET @@session.auto_increment_increment=2, @@session.auto_increment_offset=5/*!*/; /*!\C utf8mb4 *//*!*/; SET @@session.character_set_client=255,@@session.collation_connection=255,@@session.collation_server=255/*!*/; SET @@session.lc_time_names=0/*!*/; SET @@session.collation_database=DEFAULT/*!*/; /*!80011 SET @@session.default_collation_for_utf8mb4=255*//*!*/; /*!80013 SET @@session.sql_require_primary_key=0*//*!*/; CREATE TABLE Persons ( PersonID int, LastName varchar(255), FirstName varchar(255), Address varchar(255), City varchar(255) ) /*!*/;

along with in the verbose output from mysql:

--------------
CREATE TABLE Persons (
    PersonID int,
    LastName varchar(255),
    FirstName varchar(255),
    Address varchar(255),
    City varchar(255)
)
--------------

If someone can point me in the right direction it would be greatly appreciated. I’m at a loss for what to check next, and searches have produced no results thus far.

kedarpercona · July 17, 2025, 3:08pm

hello @emaN_yalpsiD and welcome to Percona Community,
Step 4 - Drop databsae test03
Step 5 - should create database test03?
Step 6 - can you try:

# extract binlog
mysqlbinlog -vv log_bin.000002 --start-position=197 --stop-position=518  > binlog.sql

# verify contents
cat binlog.sql

#load
cat binlog.sql | mysql && echo $?

Do you see any errors!? return code 0?

Currently If I copy the transaction you have posted here, everything appears in a single line starting with # and hence ignored… but let’s ignore that and follow these steps please?

emaN_yalpsiD · July 17, 2025, 4:30pm

Step 5 - Yes, the restore of the mysqldump does recreate the database test03.

Step 6 - I had to rerun the steps, so the end position changed (see output below):

$mysqlbinlog -vv log_bin.000002 --start-position=197 --stop-position=498  > backup/binlog.sql
$cat backup/binlog.sql
# The proper term is pseudo_replica_mode, but we use this compatibility alias
# to make the statement usable on server versions 8.0.24 and older.
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 126
#250717 12:19:01 server id 5  end_log_pos 126 CRC32 0xaf028d83 	Start: binlog v 4, server v 8.0.42-33 created 250717 12:19:01
# Warning: this binlog is either in use or was not closed properly.
BINLOG '
dSJ5aA8FAAAAegAAAH4AAAABAAQAOC4wLjQyLTMzAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEwANAAgAAAAABAAEAAAAYgAEGggAAAAICAgCAAAACgoKKioAEjQA
CigAAYONAq8=
'/*!*/;
# at 197
#250717 12:19:20 server id 5  end_log_pos 276 CRC32 0xbd49d29f 	GTID	last_committed=0	sequence_number=1	rbr_only=no	original_committed_timestamp=1752769160839756	immediate_commit_timestamp=1752769160839756	transaction_length=301
# original_commit_timestamp=1752769160839756 (2025-07-17 12:19:20.839756 EDT)
# immediate_commit_timestamp=1752769160839756 (2025-07-17 12:19:20.839756 EDT)
/*!80001 SET @@session.original_commit_timestamp=1752769160839756*//*!*/;
/*!80014 SET @@session.original_server_version=80042*//*!*/;
/*!80014 SET @@session.immediate_server_version=80042*//*!*/;
SET @@SESSION.GTID_NEXT= 'b3ee40ef-055c-11ee-aad1-005056a3aeb5:2'/*!*/;
# at 276
#250717 12:19:20 server id 5  end_log_pos 498 CRC32 0x441b1b7b 	Query	thread_id=126566	exec_time=0	error_code=0	Xid = 115483
use `test03`/*!*/;
SET TIMESTAMP=1752769160/*!*/;
SET @@session.pseudo_thread_id=126566/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1168113696/*!*/;
SET @@session.auto_increment_increment=2, @@session.auto_increment_offset=5/*!*/;
/*!\C utf8mb4 *//*!*/;
SET @@session.character_set_client=255,@@session.collation_connection=255,@@session.collation_server=255/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
/*!80011 SET @@session.default_collation_for_utf8mb4=255*//*!*/;
/*!80013 SET @@session.sql_require_primary_key=0*//*!*/;
CREATE TABLE Persons ( PersonID int, LastName varchar(255), FirstName varchar(255), Address varchar(255), City varchar(255) )
/*!*/;
SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;
DELIMITER ;
# End of log file
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

$cat backup/binlog.sql | mysql && echo $?
0

DB:(none)> use test03
Database changed
DB:test03> show tables;
Empty set (0.00 sec)

kedarpercona · July 18, 2025, 4:32am

Hi @emaN_yalpsiD,

When I test your script in my lab it works

# cat sql | mysql -uroot -p'x%j'
mysql: [Warning] Using a password on the command line interface can be insecure.
# mysql -uroot -p'x%j' -e "show tables from test03"
mysql: [Warning] Using a password on the command line interface can be insecure.
+------------------+
| Tables_in_test03 |
+------------------+
| Persons          |
+------------------+

You do not get any errors or warnings - which is odd. Do you get anything in error log?
Let’s test further… Does this create your table?

echo "show grants; use test03; CREATE TABLE Persons ( PersonID int, LastName varchar(255), FirstName varchar(255), Address varchar(255), City varchar(255) )" > only_create;
cat only_create | mysql

What’s source and target version for binlog and mysql?

Thanks,
K

emaN_yalpsiD · July 18, 2025, 1:46pm

I appreciate your help on this. I’m hoping it’s some minor setting I missed creating the issue. I’ve run the suggested commands and have the output below.

$echo "show grants; use test03; CREATE TABLE Persons ( PersonID int, LastName varchar(255), FirstName varchar(255), Address varchar(255), City varchar(255) )" > only_create;

$mysql
Welcome to the MySQL monitor.  Commands end with ; or \g.
Server version: 8.0.42-33 Percona Server (GPL), Release 33, Revision 9dc49998
ID:oracle DB:(none)> show databases;
+--------------------+
| Database           |
+--------------------+
| information_schema |
| mysql              |
| performance_schema |
| sys                |
+--------------------+
4 rows in set (0.00 sec)

ID:oracle DB:(none)> create database test03;
Query OK, 1 row affected (0.00 sec)

$cat only_create | mysql
Grants for oracle@localhost
GRANT SELECT, INSERT, UPDATE, DELETE, CREATE, DROP, RELOAD, SHUTDOWN, PROCESS, FILE, REFERENCES, INDEX, ALTER, SHOW DATABASES, SUPER, CREATE TEMPORARY TABLES, LOCK TABLES, EXECUTE, REPLICATION SLAVE, REPLICATION CLIENT, CREATE VIEW, SHOW VIEW, CREATE ROUTINE, ALTER ROUTINE, CREATE USER, EVENT, TRIGGER, CREATE TABLESPACE, CREATE ROLE, DROP ROLE ON *.* TO `oracle`@`localhost` WITH GRANT OPTION
GRANT APPLICATION_PASSWORD_ADMIN,AUDIT_ABORT_EXEMPT,AUDIT_ADMIN,AUTHENTICATION_POLICY_ADMIN,BACKUP_ADMIN,BINLOG_ADMIN,BINLOG_ENCRYPTION_ADMIN,CLONE_ADMIN,CONNECTION_ADMIN,ENCRYPTION_KEY_ADMIN,FIREWALL_EXEMPT,FLUSH_OPTIMIZER_COSTS,FLUSH_STATUS,FLUSH_TABLES,FLUSH_USER_RESOURCES,GROUP_REPLICATION_ADMIN,GROUP_REPLICATION_STREAM,INNODB_REDO_LOG_ARCHIVE,INNODB_REDO_LOG_ENABLE,PASSWORDLESS_USER_ADMIN,PERSIST_RO_VARIABLES_ADMIN,REPLICATION_APPLIER,REPLICATION_SLAVE_ADMIN,RESOURCE_GROUP_ADMIN,RESOURCE_GROUP_USER,ROLE_ADMIN,SENSITIVE_VARIABLES_OBSERVER,SERVICE_CONNECTION_ADMIN,SESSION_VARIABLES_ADMIN,SET_USER_ID,SHOW_ROUTINE,SYSTEM_USER,SYSTEM_VARIABLES_ADMIN,TABLE_ENCRYPTION_ADMIN,TELEMETRY_LOG_ADMIN,XA_RECOVER_ADMIN ON *.* TO `oracle`@`localhost` WITH GRANT OPTION

$mysql
Server version: 8.0.42-33 Percona Server (GPL), Release 33, Revision 9dc49998

ID:oracle DB:(none)> use test03
Database changed
ID:oracle DB:test03> show tables;
+------------------+
| Tables_in_test03 |
+------------------+
| Persons          |
+------------------+
1 row in set (0.01 sec)

All of this is being run on the same server, so there is not difference in versions to speak of.

$mysql --version
mysql  Ver 8.0.42-33 for Linux on x86_64 (Percona Server (GPL), Release 33, Revision 9dc49998)
oracle@oitpperconadg10.charlotte.edu:~
$mysqlbinlog --version
mysqlbinlog  Ver 8.0.42-33 for Linux on x86_64 (Percona Server (GPL), Release 33, Revision 9dc49998)

The error log shows no issues with the last entry being from yesterday when I restored replication. For reference, we also have the following in our config files:

binlog_expire_logs_seconds = 864000
enforce_gtid_consistency = ON
gtid_mode = ON
innodb_buffer_pool_size = 9G
innodb_flush_method = O_DIRECT
innodb_log_file_size = 1G
log_bin = log_bin
log_error = /var/lib/mysql/mysql_error.log
log_timestamps = SYSTEM
log_error_verbosity = 2
relay_log = relay_log
report_host = REDACTED
server_id = 5
auto-increment-increment = 2
auto-increment-offset = 5
[xtrabackup]
no-version-check

Thank you again for looking into this. Let me know if there is anything else I can provide that might clue us into what may be happening here.

kedarpercona · July 18, 2025, 2:00pm

Hello @emaN_yalpsiD,

I see there are no errors and you have sufficient grants… the next thing suspect is GTID.
And mostly since you’re already having the commands run against them, you are generating the GTIDs… which is why your gtid_next is getting ignored.

SET @@SESSION.GTID_NEXT= 'b3ee40ef-055c-11ee-aad1-005056a3aeb5:2'/*!*/;
...
CREATE TABLE ...

If your mysql is already having this GTID present, it will silently ignore this transaction.

create database test03
mysqldump --all-databases --log-error BACKUP_LOG --max-allowed-packet=1G --single-transaction --verbose --flush-logs --source-data=2 | gzip > BACKUP_DIR/BACKUP_FILE
CREATE TABLE Persons ( PersonID int, LastName varchar(255), FirstName varchar(255), Address varchar(255), City varchar(255) );
drop database test03

STOP HERE and
mysql -e "SHOW GLOBAL VARIABLES LIKE '%GTID%';"

Check for GTID value there and then in your backup file, check for whatever GTID_NEXT is configured before the create table command. It might already be present in gtidpurged

I’d ask you to read bout set-gtid-purged=OFF variable. Ref: https://dev.mysql.com/doc/refman/8.4/en/mysqldump.html#option_mysqldump_set-gtid-purged

Thanks,
Kedar

emaN_yalpsiD · July 18, 2025, 2:51pm

GTID was the issue. Thank you so much for that tidbit. Without any error messages, I was at a loss with the silent ignore.

ID:oracle DB:(none)> SHOW GLOBAL VARIABLES LIKE '%GTID%';
+----------------------------------+------------------------------------------+
| Variable_name                    | Value                                    |
+----------------------------------+------------------------------------------+
| binlog_gtid_simple_recovery      | ON                                       |
| enforce_gtid_consistency         | ON                                       |
| gtid_executed                    | b3ee40ef-055c-11ee-aad1-005056a3aeb5:1-3 |
| gtid_executed_compression_period | 0                                        |
| gtid_mode                        | ON                                       |
| gtid_owned                       |                                          |
| gtid_purged                      |                                          |
| session_track_gtids              | OFF                                      |
+----------------------------------+------------------------------------------+
8 rows in set (0.01 sec)

$less BACKUP_DIR/BACKUP_FILE
...
-- GTID state at the beginning of the backup
-- (origin: @@global.gtid_executed)
--
SET @@GLOBAL.GTID_PURGED=/*!80000 '+'*/ 'b3ee40ef-055c-11ee-aad1-005056a3aeb5:1';


$less backup/binlog.sql
#250718 10:13:21 server id 5  end_log_pos 276 CRC32 0x6b866490  GTID    last_committed=0        sequence_number=1       rbr_only=no     original_committed_timestamp=1752848001193733   immediate_commit_timestamp=1752848001193733   transaction_length=301
# original_commit_timestamp=1752848001193733 (2025-07-18 10:13:21.193733 EDT)
# immediate_commit_timestamp=1752848001193733 (2025-07-18 10:13:21.193733 EDT)
/*!80001 SET @@session.original_commit_timestamp=1752848001193733*//*!*/;
/*!80014 SET @@session.original_server_version=80042*//*!*/;
/*!80014 SET @@session.immediate_server_version=80042*//*!*/;
SET @@SESSION.GTID_NEXT= 'b3ee40ef-055c-11ee-aad1-005056a3aeb5:2'/*!*/;
# at 276
#250718 10:13:21 server id 5  end_log_pos 498 CRC32 0x2b664a27  Query   thread_id=131872        exec_time=0     error_code=0    Xid = 122402
use `test03`/*!*/;
SET TIMESTAMP=1752848001/*!*/;
SET @@session.pseudo_thread_id=131872/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1168113696/*!*/;
SET @@session.auto_increment_increment=2, @@session.auto_increment_offset=5/*!*/;
/*!\C utf8mb4 *//*!*/;
SET @@session.character_set_client=255,@@session.collation_connection=255,@@session.collation_server=255/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
/*!80011 SET @@session.default_collation_for_utf8mb4=255*//*!*/;
/*!80013 SET @@session.sql_require_primary_key=0*//*!*/;
CREATE TABLE Persons ( PersonID int, LastName varchar(255), FirstName varchar(255), Address varchar(255), City varchar(255) )
/*!*/;
# at 498

I ran RESET MASTER to clear out gtid_executed and gtid_purged prior to reloading the backup. Then the resulting mysqlbinlog update loaded without issue.

ID:oracle DB:(none)> reset master;
Query OK, 0 rows affected (0.01 sec)

ID:oracle DB:(none)> SHOW GLOBAL VARIABLES LIKE '%GTID%';
+----------------------------------+-------+
| Variable_name                    | Value |
+----------------------------------+-------+
| binlog_gtid_simple_recovery      | ON    |
| enforce_gtid_consistency         | ON    |
| gtid_executed                    |       |
| gtid_executed_compression_period | 0     |
| gtid_mode                        | ON    |
| gtid_owned                       |       |
| gtid_purged                      |       |
| session_track_gtids              | OFF   |
+----------------------------------+-------+
8 rows in set (0.00 sec)

$mysql < BACKUP_DIR/BACKUP_FILE

ID:oracle DB:(none)> use test03
Database changed
ID:oracle DB:test03> show tables;
Empty set (0.00 sec)

$cat backup/binlog.sql | mysql

ID:oracle DB:(none)> use test03
Database changed
ID:oracle DB:test03> show tables;
+------------------+
| Tables_in_test03 |
+------------------+
| Persons          |
+------------------+
1 row in set (0.00 sec)

Topic		Replies	Views
Replication error 1302 (GTID replication) Percona Server for MySQL 5.6	5	2324	December 2, 2014
PITR not working 'no database selected' error Percona Operator for MySQL	1	46	August 19, 2024
Mysql replica is up and running but I can't see updates on my slave Percona Server for MySQL 8.0	15	268	June 18, 2025
Binlog gaps and slow restores Percona Operator for MySQL	1	41	December 8, 2025
Percona server upgrade and replication Other MySQL® Questions	2	993	March 31, 2014

Mysqlbinlog not updating database for PITR

Related topics