Cannot read event from Percona Server 5.7.29-32-log

[taraso]

Hello,

I tried setting up ripple and making it read binlogs from PS 5.7.29. I had the issues:

1) it doesn't seem to be working when GTID mode is off on the master 2) When I turned on GTID mode, Ripple was able to connect, but the binlog file it produced seems to be corrupt:

vagrant@db11:~/mysql-ripple/data1$ mysqlbinlog --base64-output=DECODE-ROWS -vvv binlog.000000 
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#700101  0:00:00 server id 112211  end_log_pos 244  Start: binlog v 4, server v 5.6.0-ripple created 700101  0:00:00
SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;
# at 244
#700101  0:00:00 server id 101  end_log_pos 359     Start: binlog v 4, server v 5.7.29-32-log created 700101  0:00:00 at startup
ROLLBACK/*!*/;
ERROR: Error in Log_event::read_log_event(): 'Found invalid event in binary log', data_len: 43, event_type: -106
ERROR: Could not read entry at offset 359: Error in log format or read error.
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*/;

Binlog from master:

vagrant@db11:~/mysql-ripple/data1$ sudo su -
root@db11:~# cd /var/lib/mysql
root@db11:/var/lib/mysql# mysqlbinlog --base64-output=DECODE-ROWS -vvv binlog.000001 
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#210109  8:19:35 server id 101  end_log_pos 123 CRC32 0xa1b3245a    Start: binlog v 4, server v 5.7.29-32-log created 210109  8:19:35 at startup
# Warning: this binlog is either in use or was not closed properly.
ROLLBACK/*!*/;
# at 123
#210109  8:19:35 server id 101  end_log_pos 154 CRC32 0xbc7cd6d1    Previous-GTIDs
# [empty]
# at 154
#210109  8:20:06 server id 101  end_log_pos 219 CRC32 0xb4db53c3    GTID    last_committed=0    sequence_number=1   rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= '4ebd1ef0-9424-11ea-aa6c-02430e0005fc:1'/*!*/;
# at 219
#210109  8:20:06 server id 101  end_log_pos 303 CRC32 0x471500ba    Query   thread_id=106   exec_time=0 error_code=0
SET TIMESTAMP=1610180406/*!*/;
SET @@session.pseudo_thread_id=106/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1077936128/*!*/;
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/*!*/;
BEGIN
/*!*/;
# at 303
#210109  8:20:06 server id 101  end_log_pos 360 CRC32 0x248b9398    Table_map: `replication_test`.`t2` mapped to number 109
# at 360
#210109  8:20:06 server id 101  end_log_pos 400 CRC32 0x6a28cb2e    Write_rows: table id 109 flags: STMT_END_F
### INSERT INTO `replication_test`.`t2`
### SET
###   @1=2 /* INT meta=0 nullable=0 is_null=0 */
# at 400
#210109  8:20:06 server id 101  end_log_pos 431 CRC32 0xa39f38e3    Xid = 682
COMMIT/*!*/;
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*/;

on master:

mysql> show master status ;
+---------------+----------+--------------+------------------+----------------------------------------+
| File          | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set                      |
+---------------+----------+--------------+------------------+----------------------------------------+
| binlog.000001 |      431 |              |                  | 4ebd1ef0-9424-11ea-aa6c-02430e0005fc:1 |
+---------------+----------+--------------+------------------+----------------------------------------+
1 row in set (0.00 sec)

Ripple log:

vagrant@db11:~/mysql-ripple$ ./bazel-bin/rippled -ripple_datadir=./data1 -ripple_master_address=127.0.0.1 -ripple_master_port=3306 -ripple_master_user=repl -ripple_master_password=123 -ripple_server_ports=3307
WARNING: Logging before InitGoogleLogging() is written to STDERR
I0109 08:19:51.753654  4388 rippled.cc:48] InitPlugins
I0109 08:19:51.754017  4388 rippled.cc:60] Setup
I0109 08:19:51.754103  4388 binlog.cc:307] Starting binlog recovery
I0109 08:19:51.754614  4388 binlog.cc:350] Scanning binlog file: binlog.000000
I0109 08:19:51.768043  4388 binlog.cc:307] Starting binlog recovery
I0109 08:19:51.768257  4388 binlog.cc:325] Found empty index, creating new file
I0109 08:19:51.791939  4388 binlog.cc:350] Scanning binlog file: binlog.000000
I0109 08:19:51.792306  4388 binlog.cc:417] Binlog recovery complete
binlog file: binlog.000000, offset: 244, gtid:
I0109 08:19:51.792382  4388 rippled.cc:121] Recovered binlog
I0109 08:19:51.794548  4388 mysql_server_port_tcpip.cc:150] Listen on host: localhost, port: 3307
I0109 08:19:51.794705  4388 rippled.cc:62] Start
I0109 08:19:51.795480  4390 mysql_master_session.cc:182] Master session starting
I0109 08:19:51.800148  4390 mysql_client_connection.cc:148] connected to host: 127.0.0.1, port: 3306
I0109 08:19:51.807732  4390 mysql_master_session.cc:137] Connected to host: 127.0.0.1, port: 3306, server_id: 101, server_name:
W0109 08:19:51.812094  4390 mysql_master_session.cc:198] master does not support semi sync
I0109 08:19:51.812681  4390 mysql_master_session.cc:207] start replicating from ''
I0109 08:19:51.813442  4390 mysql_master_session.cc:230] Master session entering main loop
I0109 08:19:51.814479  4390 binlog.cc:626] Update binlog position to end_pos: binlog.000000:462, gtid: 0-0-0
I0109 08:19:51.814869  4390 binlog.cc:616] Skip writing event [ Previous_gtids len = 27 ]
I0109 08:19:51.815209  4390 binlog.cc:626] Update binlog position to end_pos: binlog.000000:462, gtid: 0-0-0
I0109 08:20:06.321724  4390 binlog.cc:626] Update binlog position to end_pos: binlog.000000:819, gtid: 0-0-1

My goal was to use MySQL binlogs by placing them in the ripple data dir, so that it would pick up and serve them to clients. I didn't have much luck with that though. Also, there is side a effect when Ripple wipes out binlogs it thinks are impossible to read. Any thoughts on this one?

[pushrax]

https://github.com/google/mysql-ripple/issues/25 the files produced by Ripple are a different format.

[pivanof]

@pushrax is correct, Ripple produces binlog files of a slightly different format than Percona Server/MySQL/MariaDB. Thus you cannot read them using mysqlbinlog CLI. And Ripple will not be able to read binlog files produced by MySQL as well, so you can't just put MySQL binlog files into Ripple data directory. Ripple has to download the binlogs from the master itself.

And yes, Ripple requires GTID mode to be on in order for it to be able to replicate from the master.

[taraso]

Ok, understood. This is kinda a bummer tho...

So my understanding is that the only use case for ripple would be to act as a middleman and proxy binlogs. Out of curiosity (I'm not a C/C++ dev here for sure), why not use the library/code from vanilla MySQL? I assume ripple has to provide a proper interface to clients anyway and as it reads from an upstream server it has to understand the binlogs served by those servers. But using the part of MySQL server and basically stripping off storage engine functionality + maybe adding some extra features for binlogs specifically would be an easier path? Again, an awesome work done here, I'm just finding the tool a bit limited to certain use cases, and that'd be super cool to use it for feeding binlog backups taken somehow else, for instance, or use it as a merging point of multiple source binlog backups, etc.

[leiless]

Any updates/roadmap on 2022?

I got the same error from MariaDB 10.5.12 mysqlbinlog

/*!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
#700101  8:00:00 server id 112211  end_log_pos 244  Start: binlog v 4, server v 5.6.0-ripple created 700101  8:00:00
BINLOG '
AAAAAA9TtgEA8AAAAPQAAAAAAAQANS42LjAtcmlwcGxlAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAVAAEGggAAAAAAAACAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAEEwQA
'/*!*/;
# at 244
#700101  8:00:00 server id 1  end_log_pos 492 ? 0x000a0a0a  Start: binlog v 4, server v 10.5.12-MariaDB-1:10.5.12+maria~focal-log created 700101  8:00:00 at startup
ROLLBACK/*!*/;
BINLOG '
AAAAAA8BAAAA+AAAAOwBAAAAAAQAMTAuNS4xMi1NYXJpYURCLTE6MTAuNS4xMittYXJpYX5mb2Nh
bC1sb2cAAAAAAAAAAADZCdRhEzgNAAgAEgAEBAQEEgAA5AAEGggAAAAICAgCAAAACgoKAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAEEwQADQgICAoKCgA=
'/*!*/;
ERROR: Error in Log_event::read_log_event(): 'Found invalid event in binary log', data_len: 43, event_type: 150
ERROR: Could not read entry at offset 492: Error in log format or read error.