MySQL 5.7 – Group Replication Disables Access Over TCP/IP

high-availabilityMySQLmysql-5.7replication

I'am testing new group-replication feature on MySQL 5.7 with multi-master replication on a Windows 2012 R2 system. I'm using for testing a single server and install to MySQL instance onm TCP-Ports 3306 and 3306 using diffent data-dirs and tcp-ports, etc.

All works fine, even setting up group replication. But when i use start replication, i can't connect per TCP/IP (mysql -h 127.0.0.1 -u root -p) anymore only by socket (mysql -h localhost -u root -p).

Before starting group replication on second master:

>mysql -h 127.0.0.1 -P 3307 -u root -p -e "status; show processlist; SELECT * FROM performance_schema.replication_group_members"
--------------
mysql  Ver 14.14 Distrib 5.7.17, for Win64 (x86_64)

Connection id:          16
Current database:
Current user:           root@localhost
SSL:                    Cipher in use is DHE-RSA-AES128-GCM-SHA256
Using delimiter:        ;
Server version:         5.7.17-enterprise-commercial-advanced-log MySQL Enterprise Server - Advanced Edition (Commercial)
Protocol version:       10
Connection:             127.0.0.1 via TCP/IP
Server characterset:    utf8
Db     characterset:    utf8
Client characterset:    cp850
Conn.  characterset:    cp850
TCP port:               3307
Uptime:                 2 min 52 sec

Threads: 1  Questions: 43  Slow queries: 0  Opens: 127  Flush tables: 1  Open tables: 120  Queries per second avg: 0.250
--------------

+----+------+-----------------+------+---------+------+----------+------------------+
| Id | User | Host            | db   | Command | Time | State    | Info             |
+----+------+-----------------+------+---------+------+----------+------------------+
| 16 | root | localhost:49333 | NULL | Query   |    0 | starting | show processlist |
+----+------+-----------------+------+---------+------+----------+------------------+
+---------------------------+--------------------------------------+-------------+-------------+--------------+
| CHANNEL_NAME              | MEMBER_ID                            | MEMBER_HOST | MEMBER_PORT | MEMBER_STATE |
+---------------------------+--------------------------------------+-------------+-------------+--------------+
| group_replication_applier | c6dc60ef-f8db-11e6-b78f-005056aae5b3 | RS-6-48     |        3307 | OFFLINE      |
+---------------------------+--------------------------------------+-------------+-------------+--------------+

starting group replication with mysql -P 3307 -u root -p -e "START GROUP_REPLICATION"

After that trying to connect per tcp/ip is stucked endless. The TCP-Port is open and you can connect, but nothing more. The server is only reachable by localhost:

>mysql -h localhost -P 3307 -u root -p -e "status; show processlist; SELECT * FROM performance_schema.replication_group_members"
--------------
mysql  Ver 14.14 Distrib 5.7.17, for Win64 (x86_64)

Connection id:          39
Current database:
Current user:           root@localhost
SSL:                    Cipher in use is DHE-RSA-AES128-GCM-SHA256
Using delimiter:        ;
Server version:         5.7.17-enterprise-commercial-advanced-log MySQL Enterprise Server - Advanced Edition (Commercial)
Protocol version:       10
Connection:             localhost via TCP/IP
Server characterset:    utf8
Db     characterset:    utf8
Client characterset:    cp850
Conn.  characterset:    cp850
TCP port:               3307
Uptime:                 6 min 33 sec

Threads: 4  Questions: 87  Slow queries: 0  Opens: 137  Flush tables: 1  Open tables: 130  Queries per second avg: 0.221
--------------

+----+-------------+-----------------+------+---------+------+--------------------------------------------------------+------------------+
| Id | User        | Host            | db   | Command | Time | State                                                  | Info             |
+----+-------------+-----------------+------+---------+------+--------------------------------------------------------+------------------+
| 28 | system user |                 | NULL | Connect |   30 | System lock                                            | NULL             |
| 31 | system user |                 | NULL | Connect |   30 | Slave has read all relay log; waiting for more updates | NULL             |
| 39 | root        | localhost:49358 | NULL | Query   |    0 | starting                                               | show processlist |
+----+-------------+-----------------+------+---------+------+--------------------------------------------------------+------------------+
+---------------------------+--------------------------------------+-------------+-------------+--------------+
| CHANNEL_NAME              | MEMBER_ID                            | MEMBER_HOST | MEMBER_PORT | MEMBER_STATE |
+---------------------------+--------------------------------------+-------------+-------------+--------------+
| group_replication_applier | 76c585ef-f8df-11e6-80f7-005056aae5b3 | RS-6-48     |        3306 | ONLINE       |
| group_replication_applier | c6dc60ef-f8db-11e6-b78f-005056aae5b3 | RS-6-48     |        3307 | ONLINE       |
+---------------------------+--------------------------------------+-------------+-------------+--------------+

If a stop the replication again. Server is reachable under 127.0.0.1 again.

Any hints solving this problem? Thanks.

Appendix 1: excerpt from MySQL error log when starting group replication:

2017-02-23T06:59:15.291541Z 12 [Note] Plugin group_replication reported: 'Group communication SSL configuration: group_replication_ssl_mode: "DISABLED"'
2017-02-23T06:59:15.291541Z 12 [Note] Plugin group_replication reported: 'The Winsock 2.2 dll was found okay'
2017-02-23T06:59:15.291541Z 12 [Note] Plugin group_replication reported: '[GCS] Added automatically IP ranges 10.32.6.48/8,127.0.0.1/8 to the whitelist'
2017-02-23T06:59:15.291541Z 12 [Note] Plugin group_replication reported: '[GCS] SSL was not enabled'
2017-02-23T06:59:15.291541Z 12 [Note] Plugin group_replication reported: 'Initialized group communication with configuration: group_replication_group_name: "ced7cae9-6e09-455e-9fe0-a55627f7291d"; group_replication_local_address: "10.32.6.48:3307"; group_replication_group_seeds: "10.32.6.48:3306,10.32.6.48:3307"; group_replication_bootstrap_group: false; group_replication_poll_spin_loops: 0; group_replication_compression_threshold: 1000000; group_replication_ip_whitelist: "AUTOMATIC"'
2017-02-23T06:59:15.291541Z 14 [Note] 'CHANGE MASTER TO FOR CHANNEL 'group_replication_applier' executed'. Previous state master_host='<NULL>', master_port= 0, master_log_file='', master_log_pos= 4, master_bind=''. New state master_host='<NULL>', master_port= 0, master_log_file='', master_log_pos= 4, master_bind=''.
2017-02-23T06:59:15.307218Z 12 [Note] Plugin group_replication reported: 'Group Replication applier module successfully initialized!'
2017-02-23T06:59:15.307218Z 17 [Note] Slave SQL thread for channel 'group_replication_applier' initialized, starting replication in log 'FIRST' at position 0, relay log '.\railsys-enterprise-relay-bin-group_replication_applier.000008' position: 4
2017-02-23T06:59:15.307218Z 12 [Note] Plugin group_replication reported: 'auto_increment_increment is set to 7'
2017-02-23T06:59:15.307218Z 12 [Note] Plugin group_replication reported: 'auto_increment_offset is set to 2'
2017-02-23T06:59:15.307218Z 0 [Note] Plugin group_replication reported: 'state 4257 action xa_init'
2017-02-23T06:59:15.307218Z 0 [Note] Plugin group_replication reported: 'Successfully bound to 0.0.0.0:3307 (socket=2688).'
2017-02-23T06:59:15.307218Z 0 [Note] Plugin group_replication reported: 'Successfully set listen backlog to 32 (socket=2688)!'
2017-02-23T06:59:15.307218Z 0 [Note] Plugin group_replication reported: 'Successfully unblocked socket (socket=2688)!'
2017-02-23T06:59:15.307218Z 0 [Note] Plugin group_replication reported: 'connecting to 10.32.6.48 3307'
2017-02-23T06:59:15.307218Z 0 [Note] Plugin group_replication reported: 'Ready to accept incoming connections on 0.0.0.0:3307 (socket=2688)!'
2017-02-23T06:59:15.322881Z 0 [Note] Plugin group_replication reported: 'client connected to 10.32.6.48 3307 fd 2996'
2017-02-23T06:59:15.322881Z 0 [Note] Plugin group_replication reported: 'connecting to 10.32.6.48 3307'
2017-02-23T06:59:15.338478Z 0 [Note] Plugin group_replication reported: 'client connected to 10.32.6.48 3307 fd 2696'
2017-02-23T06:59:15.338478Z 0 [Note] Plugin group_replication reported: 'connecting to 10.32.6.48 3307'
2017-02-23T06:59:15.354138Z 0 [Note] Plugin group_replication reported: 'client connected to 10.32.6.48 3307 fd 2740'
2017-02-23T06:59:15.354138Z 0 [Note] Plugin group_replication reported: 'connecting to 10.32.6.48 3307'
2017-02-23T06:59:15.369687Z 0 [Note] Plugin group_replication reported: 'client connected to 10.32.6.48 3307 fd 3000'
2017-02-23T06:59:15.369687Z 0 [Note] Plugin group_replication reported: 'connecting to 10.32.6.48 3307'
2017-02-23T06:59:15.385311Z 0 [Note] Plugin group_replication reported: 'client connected to 10.32.6.48 3307 fd 2676'
2017-02-23T06:59:15.385311Z 0 [Note] Plugin group_replication reported: 'connecting to 10.32.6.48 3307'
2017-02-23T06:59:15.400933Z 0 [Note] Plugin group_replication reported: 'client connected to 10.32.6.48 3307 fd 3004'
2017-02-23T06:59:15.400933Z 0 [Note] Plugin group_replication reported: 'connecting to 10.32.6.48 3306'
2017-02-23T06:59:15.416653Z 0 [Note] Plugin group_replication reported: 'client connected to 10.32.6.48 3306 fd 2752'
2017-02-23T06:59:16.838441Z 0 [Note] Plugin group_replication reported: 'state 4257 action xa_snapshot'
2017-02-23T06:59:16.838441Z 0 [Note] Plugin group_replication reported: 'new state x_recover'
2017-02-23T06:59:16.838441Z 0 [Note] Plugin group_replication reported: 'state 4277 action xa_complete'
2017-02-23T06:59:16.838441Z 0 [Note] Plugin group_replication reported: 'new state x_run'
2017-02-23T06:59:21.213450Z 0 [ERROR] Plugin group_replication reported: 'This member has more executed transactions than those present in the group. Local transactions: 76c585ef-f8df-11e6-80f7-005056aae5b3:1,
c6dc60ef-f8db-11e6-b78f-005056aae5b3:1,
ced7cae9-6e09-455e-9fe0-a55627f7291d:1-1501 > Group transactions: 76c585ef-f8df-11e6-80f7-005056aae5b3:1,
ced7cae9-6e09-455e-9fe0-a55627f7291d:1-1502'
2017-02-23T06:59:21.213450Z 0 [Warning] Plugin group_replication reported: 'The member contains transactions not present in the group. It is only allowed to join due to group_replication_allow_local_disjoint_gtids_join option'
2017-02-23T06:59:21.213450Z 0 [Note] Plugin group_replication reported: 'Starting group replication recovery with view_id 14877553113022027:16'
2017-02-23T06:59:21.213450Z 20 [Note] Plugin group_replication reported: 'Establishing group recovery connection with a possible donor. Attempt 1/10'
2017-02-23T06:59:27.291607Z 20 [Note] 'CHANGE MASTER TO FOR CHANNEL 'group_replication_recovery' executed'. Previous state master_host='<NULL>', master_port= 0, master_log_file='', master_log_pos= 4, master_bind=''. New state master_host='RS-6-48', master_port= 3306, master_log_file='', master_log_pos= 4, master_bind=''.
2017-02-23T06:59:27.322957Z 20 [Note] Plugin group_replication reported: 'Establishing connection to a group replication recovery donor 76c585ef-f8df-11e6-80f7-005056aae5b3 at RS-6-48 port: 3306.'
2017-02-23T06:59:27.322957Z 21 [Warning] Storing MySQL user name or password information in the master info repository is not secure and is therefore not recommended. Please consider using the USER and PASSWORD connection options for START SLAVE; see the 'START SLAVE Syntax' in the MySQL Manual for more information.
2017-02-23T06:59:27.322957Z 22 [Note] Slave SQL thread for channel 'group_replication_recovery' initialized, starting replication in log 'FIRST' at position 0, relay log '.\railsys-enterprise-relay-bin-group_replication_recovery.000001' position: 4
2017-02-23T06:59:27.322957Z 21 [Note] Slave I/O thread for channel 'group_replication_recovery': connected to master 'replication@RS-6-48:3306',replication started in log 'FIRST' at position 4
2017-02-23T06:59:27.354089Z 20 [Note] Plugin group_replication reported: 'Terminating existing group replication donor connection and purging the corresponding logs.'
2017-02-23T06:59:27.354089Z 21 [Note] Slave I/O thread killed while reading event for channel 'group_replication_recovery'
2017-02-23T06:59:27.354089Z 21 [Note] Slave I/O thread exiting for channel 'group_replication_recovery', read up to log 'railsys-enterprise-bin.000002', position 607517
2017-02-23T06:59:27.354089Z 20 [Note] 'CHANGE MASTER TO FOR CHANNEL 'group_replication_recovery' executed'. Previous state master_host='RS-6-48', master_port= 3306, master_log_file='', master_log_pos= 4, master_bind=''. New state master_host='<NULL>', master_port= 0, master_log_file='', master_log_pos= 4, master_bind=''.
2017-02-23T06:59:27.385522Z 0 [Note] Plugin group_replication reported: 'This server was declared online within the replication group'

Appendix 2:
Server A my.ini:

[mysqld]
port=3306
loose-group_replication_local_address="10.32.6.48:3306"
loose-group_replication_group_seeds="10.32.6.48:3306,10.32.6.48:3307"

Server B my.ini

[mysqld]
port=3307
loose-group_replication_local_address="10.32.6.48:3307"
loose-group_replication_group_seeds="10.32.6.48:3306,10.32.6.48:3307"

Best Answer

The MySQL error log should have some clues. Can you show the log snippet from just after you issue START GROUP_REPLICATION?

Edit: after seeing the MySQL error log snippet...

It looks like you're perhaps using the same port for the mysql protocol and the GCS (group communication system)?

You have to use different ports. For example, in your config:

[mysqld]
port=3307
group_replication_local_address = '10.32.6.48:6606'
group_replication_group_seeds = '10.32.6.49:6606,10.32.6.50:6606'

SUGGESTION

Run FLUSH BINARY LOGS; on the Master

See if the movement triggers a response from the SQL threads.

If it does not, go ahead and remove slave_parallel_workers from my.cnf and restart mysql.

Since you started MySQL up and master and slave and got error 1236, that means you are trying to establish replication from an impossible position. In the context of GTID and error message you got, the binary logs needed to fully identify a set of queries within a GTID set no longer exists,

Look back at your SHOW SLAVE STATUS\G

Retrieved_Gtid_Set: 7846a847-62c7-11e5-91a6-e06995de432e:4757140-5030085
 Executed_Gtid_Set: 7846a847-62c7-11e5-91a6-e06995de432e:1-4783274

From this, the last GTID executed is 7846a847-62c7-11e5-91a6-e06995de432e:4783274

This means that the binary log that has or had 7846a847-62c7-11e5-91a6-e06995de432e:4783275 no longer exists.

I can see this happening if you stopped replication on the Slave, left replication off long enough for the Master to rotate its binary logs (via expire_logs_days) the slave still needed to see, then turned on replication.

In your particular case, try doing a mysqlbinlog dump of the binary log mysqld-bin.000141. If nothing comes out of it, you will have to reload the Slave and setup replication from scratch.

MySQL replication with 5.7 master and 5.5 slave

From the source files, sql/log_event.h, event 34:

ANONYMOUS_GTID_LOG_EVENT= 34,

GTID wasn't introduced until 5.6, so there's no possible way a 5.5 server can understand this event (nor can the the version of mysqlbinlog that shipped with 5.5 understand it -- hence the error; you will probably be able to read this relay log if you use the version of mysqlbinlog that ships with 5.7).

It might seem like you could disable gtid_mode on the master, but there are two problems with this:

Even if that seems to work, it's completely unsupported, and only a matter of time until something else breaks. The 5.7 master can emit events the pre-5.7 slave can't handle.

when upgrading to MySQL 5.7, the slaves must be MySQL 5.7 before you can upgrade the master to 5.7. — https://dev.mysql.com/doc/refman/5.7/en/replication-upgrade.html
Any events written to the master's binlog since the upgrade are lost, from the perspective of a pre-5.7 slave, since such a server can't replicate them, so changing gtid_mode now is the equivalent of closing the barn door after the horses have escaped. This slave's data is no longer useful, unless it is upgrade to understand the master's events and can continue replicating where it stopped.

You may still be able to salvage the slave if you upgrade it to 5.7 but I see no other meaningful alternatives.

Best Answer

Related Solutions

MySQL 5.6 – GTID Replication Slave Stuck with System Lock

SUGGESTION

MySQL replication with 5.7 master and 5.5 slave

Related Question