gistfile1.txt

## The following connection tries every two seconds to connect to the RW host via 6446
## the cluster contains centos1 - centos3 with centos2 being the current primary

2020-03-06 16:41:50 routing DEBUG [7f88a3fff700] [routing:test_rw] fd=13 connection accepted at 0.0.0.0:6446
2020-03-06 16:41:50 routing DEBUG [7f88b05ff700] [routing:test_rw] fd=13 connected 127.0.0.1:49016 -> centos2:3306 as fd=14
2020-03-06 16:41:51 routing DEBUG [7f88b05ff700] [routing:test_rw] fd=13 connection closed (up: 4453b; down: 880b) 
2020-03-06 16:41:53 routing DEBUG [7f88a3fff700] [routing:test_rw] fd=13 connection accepted at 0.0.0.0:6446
2020-03-06 16:41:53 routing DEBUG [7f88b05ff700] [routing:test_rw] fd=13 connected 127.0.0.1:49020 -> centos2:3306 as fd=14
2020-03-06 16:41:53 routing DEBUG [7f88b05ff700] [routing:test_rw] fd=13 connection closed (up: 4453b; down: 880b) 
2020-03-06 16:41:55 routing DEBUG [7f88a3fff700] [routing:test_rw] fd=13 connection accepted at 0.0.0.0:6446
2020-03-06 16:41:55 routing DEBUG [7f88b05ff700] [routing:test_rw] fd=13 connected 127.0.0.1:49024 -> centos2:3306 as fd=14
2020-03-06 16:41:55 routing DEBUG [7f88b05ff700] [routing:test_rw] fd=13 connection closed (up: 4453b; down: 880b) 
2020-03-06 16:41:57 routing DEBUG [7f88a3fff700] [routing:test_rw] fd=13 connection accepted at 0.0.0.0:6446
2020-03-06 16:41:57 routing DEBUG [7f88b05ff700] [routing:test_rw] fd=13 connected 127.0.0.1:49028 -> centos2:3306 as fd=14
2020-03-06 16:41:57 routing DEBUG [7f88b05ff700] [routing:test_rw] fd=13 connection closed (up: 4453b; down: 880b) 

## Here I did use cluster.setPrimaryInstance('user@centos3:3306') in a mysqlsh to change the primary

2020-03-06 16:41:58 metadata_cache DEBUG [7f88a17fa700] Got notification from the cluster. type=3; view_id=15835059763643249:33; 
2020-03-06 16:41:58 metadata_cache DEBUG [7f88a17fa700] Got message from cluster: 11
2020-03-06 16:41:59 metadata_cache DEBUG [7f88a17fa700] GR notification listen thread has read sth from centos2:33060 on fd=10
2020-03-06 16:41:59 metadata_cache DEBUG [7f88a17fa700] Got notification from the cluster. type=3; view_id=15835059763643249:33; 
2020-03-06 16:41:59 metadata_cache DEBUG [7f88a17fa700] Got message from cluster: 11
2020-03-06 16:41:59 routing DEBUG [7f88a3fff700] [routing:test_rw] fd=13 connection accepted at 0.0.0.0:6446
2020-03-06 16:41:59 routing DEBUG [7f88b05ff700] [routing:test_rw] fd=13 connected 127.0.0.1:49046 -> centos2:3306 as fd=14
2020-03-06 16:41:59 routing DEBUG [7f88b05ff700] [routing:test_rw] fd=13 connection closed (up: 4453b; down: 880b) 
2020-03-06 16:42:00 metadata_cache DEBUG [7f88a17fa700] GR notification listen thread has read sth from centos3:33060 on fd=12
2020-03-06 16:42:00 metadata_cache DEBUG [7f88a17fa700] Got notification from the cluster. type=3; view_id=15835059763643249:33; 
2020-03-06 16:42:00 metadata_cache DEBUG [7f88a17fa700] Got message from cluster: 11

## mysqlrouter got a few notifications above, but it still connects new connections to the host that is no longer primary

2020-03-06 16:42:01 routing DEBUG [7f88a3fff700] [routing:test_rw] fd=13 connection accepted at 0.0.0.0:6446
2020-03-06 16:42:01 routing DEBUG [7f88b05ff700] [routing:test_rw] fd=13 connected 127.0.0.1:49050 -> centos2:3306 as fd=14
2020-03-06 16:42:01 routing DEBUG [7f88b05ff700] [routing:test_rw] fd=13 connection closed (up: 4453b; down: 880b) 
2020-03-06 16:42:03 routing DEBUG [7f88a3fff700] [routing:test_rw] fd=13 connection accepted at 0.0.0.0:6446
2020-03-06 16:42:03 routing DEBUG [7f88b05ff700] [routing:test_rw] fd=13 connected 127.0.0.1:49054 -> centos2:3306 as fd=14
2020-03-06 16:42:03 routing DEBUG [7f88b05ff700] [routing:test_rw] fd=13 connection closed (up: 4453b; down: 880b) 
2020-03-06 16:42:05 routing DEBUG [7f88a3fff700] [routing:test_rw] fd=13 connection accepted at 0.0.0.0:6446
2020-03-06 16:42:05 routing DEBUG [7f88b05ff700] [routing:test_rw] fd=13 connected 127.0.0.1:49058 -> centos2:3306 as fd=14
2020-03-06 16:42:05 routing DEBUG [7f88b05ff700] [routing:test_rw] fd=13 connection closed (up: 4453b; down: 880b) 
2020-03-06 16:42:07 routing DEBUG [7f88a3fff700] [routing:test_rw] fd=13 connection accepted at 0.0.0.0:6446
2020-03-06 16:42:07 routing DEBUG [7f88b05ff700] [routing:test_rw] fd=13 connected 127.0.0.1:49062 -> centos2:3306 as fd=14
2020-03-06 16:42:07 routing DEBUG [7f88b05ff700] [routing:test_rw] fd=13 connection closed (up: 4453b; down: 880b) 
2020-03-06 16:42:09 routing DEBUG [7f88a3fff700] [routing:test_rw] fd=13 connection accepted at 0.0.0.0:6446
2020-03-06 16:42:09 routing DEBUG [7f88b05ff700] [routing:test_rw] fd=13 connected 127.0.0.1:49066 -> centos2:3306 as fd=14
2020-03-06 16:42:09 routing DEBUG [7f88b05ff700] [routing:test_rw] fd=13 connection closed (up: 4453b; down: 880b) 
2020-03-06 16:42:11 routing DEBUG [7f88a3fff700] [routing:test_rw] fd=13 connection accepted at 0.0.0.0:6446
2020-03-06 16:42:11 routing DEBUG [7f88b05ff700] [routing:test_rw] fd=13 connected 127.0.0.1:49070 -> centos2:3306 as fd=14
2020-03-06 16:42:11 routing DEBUG [7f88b05ff700] [routing:test_rw] fd=13 connection closed (up: 4453b; down: 880b) 
2020-03-06 16:42:13 routing DEBUG [7f88a3fff700] [routing:test_rw] fd=13 connection accepted at 0.0.0.0:6446
2020-03-06 16:42:13 routing DEBUG [7f88b05ff700] [routing:test_rw] fd=13 connected 127.0.0.1:49074 -> centos2:3306 as fd=14
2020-03-06 16:42:13 routing DEBUG [7f88b05ff700] [routing:test_rw] fd=13 connection closed (up: 4453b; down: 880b) 
2020-03-06 16:42:15 metadata_cache DEBUG [7f88b57cf700] Connected with metadata server running on centos2:3306
2020-03-06 16:42:15 metadata_cache DEBUG [7f88b57cf700] Updating metadata information for cluster 'test'
2020-03-06 16:42:15 sql DEBUG [7f88b57cf700] Executing query: START TRANSACTION
2020-03-06 16:42:15 sql DEBUG [7f88b57cf700] Done executing query
2020-03-06 16:42:15 sql DEBUG [7f88b57cf700] Executing query: select I.mysql_server_uuid, I.endpoint, I.xendpoint from mysql_innodb_cluster_metadata.v2_instances I join mysql_innodb_cluster_metadata.v2_gr_clusters C on I.cluster_id = C.cluster_id where C.cluster_name = 'test' AND C.group_name = '3a4c9667-5fb9-11ea-9772-080027cf62cb'
2020-03-06 16:42:15 sql DEBUG [7f88b57cf700] Done executing query
2020-03-06 16:42:15 sql DEBUG [7f88b57cf700] Executing query: COMMIT
2020-03-06 16:42:15 sql DEBUG [7f88b57cf700] Done executing query
2020-03-06 16:42:15 metadata_cache DEBUG [7f88b57cf700] Updating replicaset status from GR for 'default'
2020-03-06 16:42:15 metadata_cache DEBUG [7f88b57cf700] Connected to replicaset 'default' through centos2:3306
2020-03-06 16:42:15 sql DEBUG [7f88b57cf700] Executing query: show status like 'group_replication_primary_member'
2020-03-06 16:42:15 sql DEBUG [7f88b57cf700] Done executing query
2020-03-06 16:42:15 sql DEBUG [7f88b57cf700] Executing query: SELECT member_id, member_host, member_port, member_state, @@group_replication_single_primary_mode FROM performance_schema.replication_group_members WHERE channel_name = 'group_replication_applier'
2020-03-06 16:42:15 sql DEBUG [7f88b57cf700] Done executing query
2020-03-06 16:42:15 metadata_cache DEBUG [7f88b57cf700] Replicaset 'default' has 3 members in metadata, 3 in status table
2020-03-06 16:42:15 metadata_cache DEBUG [7f88b57cf700] End updating replicaset for 'default'
2020-03-06 16:42:15 metadata_cache INFO [7f88b57cf700] Potential changes detected in cluster 'test' after metadata refresh
2020-03-06 16:42:15 metadata_cache INFO [7f88b57cf700] Metadata for cluster 'test' has 1 replicasets:
2020-03-06 16:42:15 metadata_cache INFO [7f88b57cf700] 'default' (3 members, single-master)
2020-03-06 16:42:15 metadata_cache INFO [7f88b57cf700]     centos2:3306 / 33060 - role=HA mode=RO
2020-03-06 16:42:15 metadata_cache INFO [7f88b57cf700]     centos1:3306 / 33060 - role=HA mode=RO
2020-03-06 16:42:15 metadata_cache INFO [7f88b57cf700]     centos3:3306 / 33060 - role=HA mode=RW
2020-03-06 16:42:15 routing INFO [7f88b57cf700] Routing routing:test_x_ro listening on 64470 got request to disconnect invalid connections: metadata change
2020-03-06 16:42:15 routing INFO [7f88b57cf700] Routing routing:test_x_rw listening on 64460 got request to disconnect invalid connections: metadata change
2020-03-06 16:42:15 routing INFO [7f88b57cf700] Routing routing:test_rw listening on 6446 got request to disconnect invalid connections: metadata change
2020-03-06 16:42:15 routing INFO [7f88b57cf700] Routing routing:test_ro listening on 6447 got request to disconnect invalid connections: metadata change
2020-03-06 16:42:15 metadata_cache DEBUG [7f88b57cf700] Connecting GR Notices listener on centos2:33060
2020-03-06 16:42:15 metadata_cache DEBUG [7f88b57cf700] Connected GR Notices listener on centos2:33060
2020-03-06 16:42:15 metadata_cache DEBUG [7f88b57cf700] Successfully set mysqlx_wait_timeout on connection to node centos2:33060
2020-03-06 16:42:15 metadata_cache INFO [7f88b57cf700] Enabling notices for cluster changes
2020-03-06 16:42:15 metadata_cache DEBUG [7f88b57cf700] Enabled notices for cluster changes on connection to node centos2:33060
2020-03-06 16:42:15 metadata_cache DEBUG [7f88b57cf700] Connecting GR Notices listener on centos1:33060
2020-03-06 16:42:15 metadata_cache DEBUG [7f88b57cf700] Connected GR Notices listener on centos1:33060
2020-03-06 16:42:15 metadata_cache DEBUG [7f88b57cf700] Successfully set mysqlx_wait_timeout on connection to node centos1:33060
2020-03-06 16:42:15 metadata_cache INFO [7f88b57cf700] Enabling notices for cluster changes
2020-03-06 16:42:15 metadata_cache DEBUG [7f88b57cf700] Enabled notices for cluster changes on connection to node centos1:33060
2020-03-06 16:42:15 metadata_cache DEBUG [7f88b57cf700] Connecting GR Notices listener on centos3:33060
2020-03-06 16:42:15 metadata_cache DEBUG [7f88b57cf700] Connected GR Notices listener on centos3:33060
2020-03-06 16:42:15 metadata_cache DEBUG [7f88b57cf700] Successfully set mysqlx_wait_timeout on connection to node centos3:33060
2020-03-06 16:42:15 metadata_cache INFO [7f88b57cf700] Enabling notices for cluster changes
2020-03-06 16:42:15 metadata_cache DEBUG [7f88b57cf700] Enabled notices for cluster changes on connection to node centos3:33060
2020-03-06 16:42:15 metadata_cache DEBUG [7f88a17fa700] GR notification listen thread has read sth from centos1:33060 on fd=11

## After the metadata TTL kicked in above, mysqlrouter finally switched over to centos3 (the new primary)

2020-03-06 16:42:15 routing DEBUG [7f88a3fff700] [routing:test_rw] fd=13 connection accepted at 0.0.0.0:6446
2020-03-06 16:42:15 routing DEBUG [7f88b05ff700] [routing:test_rw] fd=13 connected 127.0.0.1:49086 -> centos3:3306 as fd=14
2020-03-06 16:42:15 routing DEBUG [7f88b05ff700] [routing:test_rw] fd=13 connection closed (up: 4453b; down: 880b) 
2020-03-06 16:42:17 routing DEBUG [7f88a3fff700] [routing:test_rw] fd=13 connection accepted at 0.0.0.0:6446
2020-03-06 16:42:17 routing DEBUG [7f88b05ff700] [routing:test_rw] fd=13 connected 127.0.0.1:49090 -> centos3:3306 as fd=14
2020-03-06 16:42:17 routing DEBUG [7f88b05ff700] [routing:test_rw] fd=13 connection closed (up: 4453b; down: 880b) 
2020-03-06 16:42:19 routing DEBUG [7f88a3fff700] [routing:test_rw] fd=13 connection accepted at 0.0.0.0:6446
2020-03-06 16:42:19 routing DEBUG [7f88b05ff700] [routing:test_rw] fd=13 connected 127.0.0.1:49094 -> centos3:3306 as fd=14
2020-03-06 16:42:20 routing DEBUG [7f88b05ff700] [routing:test_rw] fd=13 connection closed (up: 4453b; down: 880b)