Unable to set up mysql semi sync with ripple about mysql-ripple HOT 9 OPEN

The MySQL logs that you posted seem to indicate that Ripple doesn't send semi-sync replies, but Ripple logs don't indicate why. So it's hard to say what's the problem. Maybe you can add more logging to the code here https://github.com/google/mysql-ripple/blob/master/mysql_master_session.cc#L253 to understand what's happening and why Ripple doesn't send semi-sync replies?

from mysql-ripple.

Thank you for your reply !!!

I add logging as you suggested, looks like semi_sync_reply always 0, GetSemiSyncSlaveReplyActive() return 1 => bool reply always 0 in my case

So I delete semi_sync_reply like below just for testing :

  bool reply = GetSemiSyncSlaveReplyActive();
  //LOG(INFO) << "semi_sync_reply is: " << semi_sync_reply;
  LOG(INFO) << "method: " << GetSemiSyncSlaveReplyActive();
  LOG(INFO) << "reply from semi sync is: " << reply;
  if (!binlog_->AddEvent(event, reply)) {
    LOG(ERROR) << "Failed to add event to binlog";
    break;
  }

  if (reply) {
    FilePosition file_pos =
        binlog_->GetBinlogPosition().latest_master_position;
    if (!SendSemiSyncReply(file_pos)) {
      LOG(WARNING) << "Failed to send semi sync reply";
      break;
    } else {
      LOG(INFO) << "SendSemiSyncReply is true: send smi sync reply succeed";
    }
  }

Ripple logs:

r_port=3306 -ripple_master_user=repl_user -ripple_master_password=root123 -ripple_server_ports=15000 -ripple_semi_sync_slave_enabled=true
WARNING: Logging before InitGoogleLogging() is written to STDERR
I0302 05:46:51.246495 114714 rippled.cc:48] InitPlugins
I0302 05:46:51.246569 114714 rippled.cc:60] Setup
I0302 05:46:51.246594 114714 binlog.cc:307] Starting binlog recovery
I0302 05:46:51.246752 114714 binlog.cc:350] Scanning binlog file: binlog.000000
I0302 05:46:51.784989 114714 binlog.cc:417] Binlog recovery complete
binlog file: binlog.000000, offset: 11591202, gtid: 02b13200-56ca-11ea-945b-000d3aa16eab:0-0-1
I0302 05:46:51.785027 114714 rippled.cc:121] Recovered binlog
I0302 05:46:51.785503 114714 mysql_server_port_tcpip.cc:150] Listen on host: localhost, port: 15000
I0302 05:46:51.785544 114714 rippled.cc:62] Start
I0302 05:46:51.785815 114716 mysql_master_session.cc:182] Master session starting
I0302 05:46:51.789144 114716 mysql_client_connection.cc:148] connected to host: 172.16.4.4, port: 3306
I0302 05:46:51.791885 114716 mysql_master_session.cc:137] Connected to host: 172.16.4.4, port: 3306, server_id: 1, server_name:
I0302 05:46:51.793169 114716 mysql_master_session.cc:202] master has semi sync enabled
I0302 05:46:51.793195 114716 mysql_master_session.cc:207] start replicating from '02b13200-56ca-11ea-945b-000d3aa16eab:0-0-1'
I0302 05:46:51.793565 114716 mysql_master_session.cc:230] Master session entering main loop
I0302 05:46:51.793905 114716 binlog.cc:626] Update binlog position to end_pos: binlog.000000:11591265, gtid: 0-0-1

I0302 05:46:51.793931 114716 mysql_master_session.cc:255] method: 1
I0302 05:46:51.793941 114716 mysql_master_session.cc:256] reply from semi sync is: 1

I0302 05:46:51.793952 114716 binlog.cc:616] Skip writing event [ Previous_gtids len = 27 ]
I0302 05:46:51.793967 114716 binlog.cc:626] Update binlog position to end_pos: binlog.000000:11591265, gtid: 0-0-1

I0302 05:46:51.793999 114716 mysql_master_session.cc:269] SendSemiSyncReply is true: send smi sync reply succeed

I0302 05:46:51.794016 114716 mysql_master_session.cc:255] method: 1
I0302 05:46:51.794021 114716 mysql_master_session.cc:256] reply from semi sync is: 1
I0302 05:46:51.794045 114716 mysql_master_session.cc:269] SendSemiSyncReply is true: send smi sync reply succeed
E0302 05:46:51.794075 114716 mysql_master_session.cc:303] Failed to read packet: Got error reading packet from server: Lost connection to MySQL server during query
I0302 05:46:51.794091 114716 binlog.cc:675] Connection closed last position binlog file: binlog.000000:11591265, gtid: 0-0-1
I0302 05:46:51.794113 114716 mysql_master_session.cc:278] Disconnecting from master
I0302 05:46:51.795538 114716 mysql_client_connection.cc:148] connected to host: 172.16.4.4, port: 3306
I0302 05:46:51.798288 114716 mysql_master_session.cc:137] Connected to host: 172.16.4.4, port: 3306, server_id: 1, server_name:
I0302 05:46:51.799501 114716 mysql_master_session.cc:202] master has semi sync enabled
I0302 05:46:51.799525 114716 mysql_master_session.cc:207] start replicating from '02b13200-56ca-11ea-945b-000d3aa16eab:0-0-1'
I0302 05:46:51.799897 114716 mysql_master_session.cc:230] Master session entering main loop
....

Seems running ??? But never stop...

Does that means ripple are sending semi-sync replies back ?

from mysql-ripple.

If semi_sync_reply is always 0, it means that master doesn't request for the semi-sync ack. It sounds a little strange, why would master do that. Are you using vanilla MySQL?

from mysql-ripple.

No, I don't even know what is vanilla MySQL, I reran again, with the logging, so looks like semi_sync_reply do change to 1 at some time,

code:
bool reply = semi_sync_reply && GetSemiSyncSlaveReplyActive();

  LOG(INFO) << "reply from semi sync is: " << reply;
  if (!binlog_->AddEvent(event, reply)) {
    LOG(ERROR) << "Failed to add event to binlog";
    break;
  }
  //LOG(INFO) << "Before if reply, current value of reply is : " << reply;
  if (reply) {
    FilePosition file_pos =
        binlog_->GetBinlogPosition().latest_master_position;
    if (!SendSemiSyncReply(file_pos)) {
      LOG(WARNING) << "Failed to send semi sync reply";
      break;
    } else {
      LOG(INFO) << "SendSemiSyncReply is true: send smi sync reply succeed";
    }
  }

``
Before running:

Master
mysql> show variables like '%Rpl%';
+-------------------------------------------+------------+
| Variable_name | Value |
+-------------------------------------------+------------+
| rpl_semi_sync_master_enabled | ON |
| rpl_semi_sync_master_timeout | 100000 |
| rpl_semi_sync_master_trace_level | 32 |
| rpl_semi_sync_master_wait_for_slave_count | 1 |
| rpl_semi_sync_master_wait_no_slave | ON |
| rpl_semi_sync_master_wait_point | AFTER_SYNC |
| rpl_stop_slave_timeout | 31536000 |
+-------------------------------------------+------------+:

Start running a short 60s sys bench test:

Master log from beginning:

2020-03-03T03:58:45.134848Z 5 [Note] Start binlog_dump to master_thread_id(5) slave_server(112211), pos(, 4)
2020-03-03T03:58:45.134905Z 5 [Note] Start semi-sync binlog_dump to slave (server_id: 112211), pos(, 4)
2020-03-03T03:59:27.940465Z 0 [ERROR] /usr/sbin/mysqld: Got packets out of order
2020-03-03T03:59:27.940518Z 0 [ERROR] /usr/sbin/mysqld: Got packets out of order
2020-03-03T03:59:27.940552Z 0 [ERROR] /usr/sbin/mysqld: Couldn't uncompress communication packet
2020-03-03T03:59:27.940567Z 0 [ERROR] /usr/sbin/mysqld: Got packets out of order
2020-03-03T03:59:27.940586Z 0 [ERROR] /usr/sbin/mysqld: Got packets out of order
2020-03-03T03:59:27.940601Z 0 [ERROR] /usr/sbin/mysqld: Got an error reading communication packets

2020-03-03T03:59:27.940804Z 5 [ERROR] Semi-sync master failed on net_flush() before waiting for slave reply

2020-03-03T03:59:27.940834Z 5 [Note] Stop semi-sync binlog_dump to slave (server_id: 112211)
2020-03-03T03:59:27.940854Z 5 [Note] Aborted connection 5 to db: 'unconnected' user: 'repl_user' host: 'perf-slave.internal.cloudapp.net' (Found net error)
2020-03-03T03:59:27.946870Z 20 [Note] Start binlog_dump to master_thread_id(20) slave_server(112211), pos(, 4)
2020-03-03T03:59:27.946910Z 20 [Note] Start semi-sync binlog_dump to slave (server_id: 112211), pos(, 4)
2020-03-03T03:59:27.947564Z 20 [ERROR] Semi-sync master failed on net_flush() before waiting for slave reply
2020-03-03T03:59:27.947590Z 20 [Note] Stop semi-sync binlog_dump to slave (server_id: 112211)
2020-03-03T03:59:27.947609Z 20 [Note] Aborted connection 20 to db: 'unconnected' user: 'repl_user' host: 'perf-slave.internal.cloudapp.net' (Found net error)

…...

2020-03-03T03:59:28.107392Z 29 [Note] Start binlog_dump to master_thread_id(29) slave_server(112211), pos(, 4)
2020-03-03T03:59:28.107436Z 29 [Note] Start semi-sync binlog_dump to slave (server_id: 112211), pos(, 4)

2020-03-03T04:01:07.939990Z 10 [Warning] Timeout waiting for reply of binlog (file: mysql-bin.000003, pos: 1000), semi-sync up to file , position 4.

2020-03-03T04:01:07.940046Z 10 [Note] Semi-sync replication switched OFF.

Ripple:

WARNING: Logging before InitGoogleLogging() is written to STDERR)
I0303 03:58:45.077606 58650 rippled.cc:48] InitPlugins
I0303 03:58:45.077679 58650 rippled.cc:60] Setup
I0303 03:58:45.077705 58650 binlog.cc:307] Starting binlog recovery
I0303 03:58:45.077872 58650 binlog.cc:350] Scanning binlog file: binlog.000000
I0303 03:58:45.078395 58650 binlog.cc:417] Binlog recovery complete
binlog file: binlog.000000, offset: 13645, gtid: 02b13200-56ca-11ea-945b-000d3aa16eab:0-0-20
I0303 03:58:45.078423 58650 rippled.cc:121] Recovered binlog
I0303 03:58:45.078850 58650 mysql_server_port_tcpip.cc:150] Listen on host: localhost, port: 15000
I0303 03:58:45.078891 58650 rippled.cc:62] Start
I0303 03:58:45.079146 58652 mysql_master_session.cc:182] Master session starting_datadir=/mnt/data -ripple_master_address=172.16.4.4 -ripple_masterI0303 03:58:45.123920 58652 mysql_client_connection.cc:148] connected to host: 172.16.4.4, port: 3306
I0303 03:58:45.127638 58652 mysql_master_session.cc:137] Connected to host: 172.16.4.4, port: 3306, server_id: 1, server_name:
I0303 03:58:45.128952 58652 mysql_master_session.cc:202] master has semi sync enabled
I0303 03:58:45.128983 58652 mysql_master_session.cc:207] start replicating from '02b13200-56ca-11ea-945b-000d3aa16eab:0-0-20'
I0303 03:58:45.129371 58652 mysql_master_session.cc:230] Master session entering main loop
I0303 03:58:45.129760 58652 binlog.cc:626] Update binlog position to end_pos: binlog.000000:13708, gtid: 0-0-20
I0303 03:58:45.129787 58652 mysql_master_session.cc:256] reply from semi sync is: 0
I0303 03:58:45.129814 58652 binlog.cc:616] Skip writing event [ Previous_gtids len = 67 ]
I0303 03:58:45.129837 58652 binlog.cc:626] Update binlog position to end_pos: binlog.000000:13708, gtid: 0-0-20
………

I0303 03:58:45.229821 58652 mysql_master_session.cc:256] reply from semi sync is: 0
I0303 03:59:27.934952 58652 mysql_master_session.cc:256] reply from semi sync is: 0
I0303 03:59:27.934984 58652 mysql_master_session.cc:256] reply from semi sync is: 1
I0303 03:59:27.935034 58652 binlog.cc:626] Update binlog position to end_pos: binlog.000000:14594, gtid: 0-0-21

I0303 03:59:27.935078 58652 mysql_master_session.cc:269] SendSemiSyncReply is true: send smi sync reply succeed

E0303 03:59:27.935127 58652 mysql_master_session.cc:303] Failed to read packet: Got error reading packet from server: Lost connection to MySQL server during query
I0303 03:59:27.935153 58652 binlog.cc:675] Connection closed last position binlog file: binlog.000000:14594, gtid: 0-0-21
I0303 03:59:27.935178 58652 mysql_master_session.cc:278] Disconnecting from master
I0303 03:59:27.936650 58652 mysql_client_connection.cc:148] connected to host: 172.16.4.4, port: 3306
I0303 03:59:27.939680 58652 mysql_master_session.cc:137] Connected to host: 172.16.4.4, port: 3306, server_id: 1, server_name:
I0303 03:59:27.940980 58652 mysql_master_session.cc:202] master has semi sync enabled
I0303 03:59:27.941006 58652 mysql_master_session.cc:207] start replicating from '02b13200-56ca-11ea-945b-000d3aa16eab:0-0-21'
I0303 03:59:27.941398 58652 mysql_master_session.cc:230] Master session entering main loop
I0303 03:59:27.941757 58652 binlog.cc:626] Update binlog position to end_pos: binlog.000000:14657, gtid: 0-0-21
I0303 03:59:27.941782 58652 mysql_master_session.cc:256] reply from semi sync is: 0

I0303 03:59:27.941793 58652 binlog.cc:616] Skip writing event [ Previous_gtids len = 67 ]
I0303 03:59:27.941807 58652 binlog.cc:626] Update binlog position to end_pos: binlog.000000:14657, gtid: 0-0-21

I0303 03:59:27.941815 58652 mysql_master_session.cc:256] reply from semi sync is: 0
I0303 03:59:27.941835 58652 mysql_master_session.cc:256] reply from semi sync is: 0
......

I0303 03:59:27.942019 58652 mysql_master_session.cc:256] reply from semi sync is: 1
I0303 03:59:27.942057 58652 binlog.cc:626] Update binlog position to end_pos: binlog.000000:15543, gtid: 0-0-22

I0303 03:59:27.942097 58652 mysql_master_session.cc:269] SendSemiSyncReply is true: send smi sync reply succeed

E0303 03:59:27.942142 58652 mysql_master_session.cc:303] Failed to read packet: Got error reading packet from server: Lost connection to MySQL server during query
I0303 03:59:27.942167 58652 binlog.cc:675] Connection closed last position binlog file: binlog.000000:15543, gtid: 0-0-22

from mysql-ripple.

So far
Master:

1. rpl_semi_sync_master_wait_for_slave_count =1 since mysql start
2. Those "[ERROR] /usr/sbin/mysqld: Got packets out of order" on master are the first line of log when I am start running sys bench.
3. I set rpl_semi_sync_master_timeout to 100000 which I think should be enough for now ? (As running semi sync without ripple and I set to to default 1s don't have any issues)

Ripple side,

1. semi_sync_reply change to 1 and sending reply back succeed
   https://github.com/google/mysql-ripple/blob/master/mysql_master_session.cc#L261
2. Not sure why it's throwing this "E0303 03:59:27.942142 58652 mysql_master_session.cc:303] Failed to read packet: Got error reading packet from server: Lost connection to MySQL server during query"

from mysql-ripple.

One more thing, master & ripple are on 2 VMs under same vnet/region/OS/disk.. etc

from mysql-ripple.

Any updates ?

from mysql-ripple.

Sorry for the late reply...
Looking through the logs I have an impression that things work properly initially. First some binlog events don't need sem-sync reply, because they are in the middle of a transaction, thus master doesn't request the reply. Then COMMIT event requires reply and master requests it. Ripple successfully sends the reply, but then the master for some reason doesn't understand this reply and breaks the connection from Ripple. Then Ripple reconnects, again receives a few binlog events, but when it tries to send semi-sync reply, master breaks the connection.
Why master doesn't understand what Ripple sends to it, I'm not sure. I guess some more debugging inside MySQL code needs to be done to understand that... Which exact MySQL version are you using? Did you just downloaded it from MySQL website?

from mysql-ripple.

Thank you for you reply, i am using mysql Ver 14.14 Distrib 5.7.29, for Linux (x86_64), I installed on ubuntu linux Azure VM and I only ran two commands: sudo apt update, sudo apt install mysql-server

mysql> show variables like '%version%';
+-------------------------+-------------------------+
| Variable_name | Value |
+-------------------------+-------------------------+
| innodb_version | 5.7.29 |
| protocol_version | 10 |
| slave_type_conversions | |
| tls_version | TLSv1,TLSv1.1,TLSv1.2 |
| version | 5.7.29-0ubuntu0.18.04.1 |
| version_comment | (Ubuntu) |
| version_compile_machine | x86_64 |
| version_compile_os | Linux |
+-------------------------+-------------------------+

from mysql-ripple.