Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Leader switch When xenon on slave node quit #26

Open
andyli029 opened this issue Apr 7, 2021 · 4 comments
Open

Leader switch When xenon on slave node quit #26

andyli029 opened this issue Apr 7, 2021 · 4 comments
Assignees
@andyli029 @runkecheng
Labels
enhancement New feature or request

Comments

@andyli029
Copy link
Contributor

andyli029 commented Apr 7, 2021 •
edited
Loading

Summary

Leader switch When xenon on slave node quit
It is noise:

test-krypton-1: The old leader ->the new slave 

2021/04/07 11:39:21.222243 api.go:280: [INFO] mysql.slave.status:&{ 0 false false }

2021/04/07 11:39:21.222424 api.go:290: [INFO] mysql.master.status:&{mysql-bin.000002 154 true true 0 }

2021/04/07 11:39:22.973750 trace.go:37: [ERROR] LEADER[ID:test-krypton-1.test-krypton.default.svc.cluster.local:8801, V:11, E:2].send.heartbeat.to.peer[test-krypton-0.test-krypton.default.svc.cluster.local:8801].new.client.error[dial tcp: lookup test-krypton-0.test-krypton.default.svc.cluster.local: no such host]

2021/04/07 11:39:22.973784 trace.go:37: [ERROR] LEADER[ID:test-krypton-1.test-krypton.default.svc.cluster.local:8801, V:11, E:2].send.heartbeat.get.rsp[N:, V:0, E:0].error[ErrorRpcCall]

2021/04/07 11:39:24.974169 trace.go:37: [ERROR] LEADER[ID:test-krypton-1.test-krypton.default.svc.cluster.local:8801, V:11, E:2].send.heartbeat.to.peer[test-krypton-0.test-krypton.default.svc.cluster.local:8801].new.client.error[dial tcp: lookup test-krypton-0.test-krypton.default.svc.cluster.local: no such host]

2021/04/07 11:39:24.974207 trace.go:37: [ERROR] LEADER[ID:test-krypton-1.test-krypton.default.svc.cluster.local:8801, V:11, E:2].send.heartbeat.get.rsp[N:, V:0, E:0].error[ErrorRpcCall]

2021/04/07 11:39:25.227313 trace.go:32: [WARNING] LEADER[ID:test-krypton-1.test-krypton.default.svc.cluster.local:8801, V:11, E:2].get.voterequest.from[{Raft:{EpochID:2 ViewID:12 Leader: From:test-krypton-0.test-krypton.default.svc.cluster.local:8801 To:test-krypton-1.test-krypton.default.svc.cluster.local:8801 State:} Repl:{Master_Host: Master_Port:0 Repl_User: Repl_Password:} GTID:{Master_Log_File:mysql-bin.000002 Read_Master_Log_Pos:154 Relay_Master_Log_File: Slave_IO_Running:false Slave_IO_Running_Str:No Slave_SQL_Running:true Slave_SQL_Running_Str:Yes Retrieved_GTID_Set: Executed_GTID_Set: Seconds_Behind_Master: Slave_SQL_Running_State:Slave has read all relay log; waiting for more updates Last_Error: Last_IO_Error: Last_SQL_Error:} Peers:[] IdlePeers:[]}]

2021/04/07 11:39:25.227571 api.go:280: [INFO] mysql.slave.status:&{ 0 false false }

2021/04/07 11:39:25.228121 api.go:290: [INFO] mysql.master.status:&{mysql-bin.000002 154 true true 0 }

2021/04/07 11:39:25.228151 api.go:104: [WARNING] mysql.gtid.compare.this[{mysql-bin.000002 154 true true 0 }].from[&{mysql-bin.000002 154 false No true Yes Slave has read all relay log; waiting for more updates }]

2021/04/07 11:39:25.228165 trace.go:32: [WARNING] LEADER[ID:test-krypton-1.test-krypton.default.svc.cluster.local:8801, V:11, E:2].get.requestvote.from[N:test-krypton-0.test-krypton.default.svc.cluster.local:8801, V:12, E:2].degrade.to.follower

2021/04/07 11:39:25.228172 trace.go:32: [WARNING] LEADER[ID:test-krypton-1.test-krypton.default.svc.cluster.local:8801, V:11, E:2].do.updateViewID[FROM:11 TO:12]

2021/04/07 11:39:25.228177 trace.go:32: [WARNING] LEADER[ID:test-krypton-1.test-krypton.default.svc.cluster.local:8801, V:12, E:2].degrade.to.follower.stop.the.vip...

2021/04/07 11:39:25.334647 trace.go:32: [WARNING] LEADER[ID:test-krypton-1.test-krypton.default.svc.cluster.local:8801, V:12, E:2].leaderStopShellCommand[[-c /scripts/leader-stop.sh]].done

2021/04/07 11:39:25.334685 trace.go:27: [INFO] LEADER[ID:test-krypton-1.test-krypton.default.svc.cluster.local:8801, V:12, E:2].check.semi-sync.thread.stop...

2021/04/07 11:39:25.334692 trace.go:27: [INFO] LEADER[ID:test-krypton-1.test-krypton.default.svc.cluster.local:8801, V:12, E:2].check.gtid.thread.stop...

2021/04/07 11:39:25.334712 trace.go:32: [WARNING] FOLLOWER[ID:test-krypton-1.test-krypton.default.svc.cluster.local:8801, V:12, E:2].leader.state.machine.exit.done

2021/04/07 11:39:25.334719 trace.go:27: [INFO] FOLLOWER[ID:test-krypton-1.test-krypton.default.svc.cluster.local:8801, V:12, E:2].start.CheckBrainSplit

2021/04/07 11:39:25.334739 trace.go:32: [WARNING] FOLLOWER[ID:test-krypton-1.test-krypton.default.svc.cluster.local:8801, V:12, E:2].state.init

2021/04/07 11:39:25.510949 trace.go:32: [WARNING] FOLLOWER[ID:test-krypton-1.test-krypton.default.svc.cluster.local:8801, V:12, E:2].leaderStopShellCommand[[-c /scripts/leader-stop.sh]].done

2021/04/07 11:39:25.510996 trace.go:32: [WARNING] FOLLOWER[ID:test-krypton-1.test-krypton.default.svc.cluster.local:8801, V:12, E:2].mysql.waitMysqlDoneAsync.prepare

2021/04/07 11:39:25.511017 trace.go:32: [WARNING] FOLLOWER[ID:test-krypton-1.test-krypton.default.svc.cluster.local:8801, V:12, E:2].state.machine.run

2021/04/07 11:39:26.228289 trace.go:32: [WARNING] FOLLOWER[ID:test-krypton-1.test-krypton.default.svc.cluster.local:8801, V:12, E:2].mysql.SetReadOnly.done

2021/04/07 11:39:26.228474 api.go:376: [ERROR] mysql[localhost:3306].SetSlaveGlobalSysVar.error[Error 1193: Unknown system variable 'tokudb_fsync_log_period'].var[SET GLOBAL tokudb_fsync_log_period=1000]

2021/04/07 11:39:26.228749 api.go:379: [WARNING] mysql[localhost:3306].SetSlaveGlobalSysVar[tokudb_fsync_log_period=1000;sync_binlog=1000;innodb_flush_log_at_trx_commit=1]

2021/04/07 11:39:26.228774 trace.go:37: [ERROR] FOLLOWER[ID:test-krypton-1.test-krypton.default.svc.cluster.local:8801, V:12, E:2].mysql.SetSlaveGlobalSysVar.error[Error 1193: Unknown system variable 'tokudb_fsync_log_period']

2021/04/07 11:39:26.228782 trace.go:32: [WARNING] FOLLOWER[ID:test-krypton-1.test-krypton.default.svc.cluster.local:8801, V:12, E:2].mysql.SetSlaveGlobalSysVar.done

2021/04/07 11:39:26.228789 trace.go:32: [WARNING] FOLLOWER[ID:test-krypton-1.test-krypton.default.svc.cluster.local:8801, V:12, E:2].prepareAsync.done

2021/04/07 11:39:26.245368 trace.go:37: [ERROR] FOLLOWER[ID:test-krypton-1.test-krypton.default.svc.cluster.local:8801, V:12, E:2].mysql.StartSlave.error[Error 1200: The server is not configured as slave; fix in config file or with CHANGE MASTER TO]

2021/04/07 11:39:26.245396 api.go:280: [INFO] mysql.slave.status:&{ 0 false false }

2021/04/07 11:39:26.245575 api.go:290: [INFO] mysql.master.status:&{mysql-bin.000002 154 true true 0 }

2021/04/07 11:39:26.245593 trace.go:32: [WARNING] FOLLOWER[ID:test-krypton-1.test-krypton.default.svc.cluster.local:8801, V:12, E:2].init.my.gtid.is:{mysql-bin.000002 154 true true 0 }

2021/04/07 11:39:26.245619 api.go:280: [INFO] mysql.slave.status:&{ 0 false false }

2021/04/07 11:39:26.308777 api.go:290: [INFO] mysql.master.status:&{mysql-bin.000002 154 true true 0 }

2021/04/07 11:39:26.308839 trace.go:32: [WARNING] FOLLOWER[ID:test-krypton-1.test-krypton.default.svc.cluster.local:8801, V:12, E:2].get.heartbeat.my.gtid.is:{mysql-bin.000002 154 true true 0 }

2021/04/07 11:39:26.309177 trace.go:32: [WARNING] FOLLOWER[ID:test-krypton-1.test-krypton.default.svc.cluster.local:8801, V:12, E:2].get.heartbeat.from[N:test-krypton-0.test-krypton.default.svc.cluster.local:8801, V:12, E:2].change.mysql.master

2021/04/07 11:39:26.345505 trace.go:32: [WARNING] FOLLOWER[ID:test-krypton-1.test-krypton.default.svc.cluster.local:8801, V:12, E:2].get.heartbeat.change.to.the.new.master[test-krypton-0.test-krypton.default.svc.cluster.local:8801].successed

test-krypton-0: the old slave ->the new leader

2021/04/07 11:39:20.006492 trace.go:32: [WARNING] FOLLOWER[ID:test-krypton-0.test-krypton.default.svc.cluster.local:8801, V:11, E:2].ping.responses[1].is.less.than.half.maybe.brain.split

2021/04/07 11:39:20.009268 trace.go:32: [WARNING] FOLLOWER[ID:test-krypton-0.test-krypton.default.svc.cluster.local:8801, V:11, E:2].ping.responses[2].is.greater.than.half.again

2021/04/07 11:39:25.218234 trace.go:32: [WARNING] FOLLOWER[ID:test-krypton-0.test-krypton.default.svc.cluster.local:8801, V:11, E:2].timeout.to.do.new.election

2021/04/07 11:39:25.218766 api.go:280: [INFO] mysql.slave.status:&{mysql-bin.000002 154 false No true Yes Slave has read all relay log; waiting for more updates }

2021/04/07 11:39:25.218785 api.go:56: [WARNING] mysql[localhost:3306].Promotable.sql_thread[true]

2021/04/07 11:39:25.218793 trace.go:32: [WARNING] FOLLOWER[ID:test-krypton-0.test-krypton.default.svc.cluster.local:8801, V:11, E:2].timeout.and.ping.almost.node.successed.promote.to.candidate

2021/04/07 11:39:25.219031 trace.go:32: [WARNING] CANDIDATE[ID:test-krypton-0.test-krypton.default.svc.cluster.local:8801, V:11, E:2].follower.state.machine.exit

2021/04/07 11:39:25.219056 trace.go:32: [WARNING] CANDIDATE[ID:test-krypton-0.test-krypton.default.svc.cluster.local:8801, V:11, E:2].state.machine.run

2021/04/07 11:39:25.219098 trace.go:32: [WARNING] CANDIDATE[ID:test-krypton-0.test-krypton.default.svc.cluster.local:8801, V:12, E:2].prepare.send.requestvote.to[test-krypton-2.test-krypton.default.svc.cluster.local:8801]

2021/04/07 11:39:25.219192 trace.go:32: [WARNING] CANDIDATE[ID:test-krypton-0.test-krypton.default.svc.cluster.local:8801, V:12, E:2].prepare.send.requestvote.to[test-krypton-1.test-krypton.default.svc.cluster.local:8801]

2021/04/07 11:39:25.219569 api.go:280: [INFO] mysql.slave.status:&{mysql-bin.000002 154 false No true Yes Slave has read all relay log; waiting for more updates }

2021/04/07 11:39:25.219621 trace.go:32: [WARNING] CANDIDATE[ID:test-krypton-0.test-krypton.default.svc.cluster.local:8801, V:12, E:2].send.requestvote.to.peer[test-krypton-2.test-krypton.default.svc.cluster.local:8801].request.gtid[{mysql-bin.000002 154 false No true Yes Slave has read all relay log; waiting for more updates }]

2021/04/07 11:39:25.219706 api.go:280: [INFO] mysql.slave.status:&{mysql-bin.000002 154 false No true Yes Slave has read all relay log; waiting for more updates }

2021/04/07 11:39:25.219726 trace.go:32: [WARNING] CANDIDATE[ID:test-krypton-0.test-krypton.default.svc.cluster.local:8801, V:12, E:2].send.requestvote.to.peer[test-krypton-1.test-krypton.default.svc.cluster.local:8801].request.gtid[{mysql-bin.000002 154 false No true Yes Slave has read all relay log; waiting for more updates }]

2021/04/07 11:39:25.226070 trace.go:32: [WARNING] CANDIDATE[ID:test-krypton-0.test-krypton.default.svc.cluster.local:8801, V:12, E:2].send.requestvote.done.to[test-krypton-2.test-krypton.default.svc.cluster.local:8801]

2021/04/07 11:39:25.332622 trace.go:32: [WARNING] CANDIDATE[ID:test-krypton-0.test-krypton.default.svc.cluster.local:8801, V:12, E:2].send.requestvote.done.to[test-krypton-1.test-krypton.default.svc.cluster.local:8801]

2021/04/07 11:39:25.332677 trace.go:32: [WARNING] CANDIDATE[ID:test-krypton-0.test-krypton.default.svc.cluster.local:8801, V:12, E:2].get.vote.response.from[N:test-krypton-2.test-krypton.default.svc.cluster.local:8801, R:FOLLOWER].rsp.gtid[{mysql-bin.000002 154 false No true Yes Slave has read all relay log; waiting for more updates }].retcode[OK]

2021/04/07 11:39:25.332690 trace.go:27: [INFO] CANDIDATE[ID:test-krypton-0.test-krypton.default.svc.cluster.local:8801, V:12, E:2].get.vote.response.from[N:test-krypton-2.test-krypton.default.svc.cluster.local:8801, V:11].ok.votegranted[2].majoyrity[2]

2021/04/07 11:39:25.332705 trace.go:32: [WARNING] CANDIDATE[ID:test-krypton-0.test-krypton.default.svc.cluster.local:8801, V:12, E:2].get.vote.response.from[N:test-krypton-1.test-krypton.default.svc.cluster.local:8801, R:LEADER].rsp.gtid[{mysql-bin.000002 154 true true 0 }].retcode[OK]

2021/04/07 11:39:25.332725 trace.go:27: [INFO] CANDIDATE[ID:test-krypton-0.test-krypton.default.svc.cluster.local:8801, V:12, E:2].get.vote.response.from[N:test-krypton-1.test-krypton.default.svc.cluster.local:8801, V:11].ok.votegranted[3].majoyrity[2]

2021/04/07 11:39:25.332733 trace.go:32: [WARNING] CANDIDATE[ID:test-krypton-0.test-krypton.default.svc.cluster.local:8801, V:12, E:2].grants.unanimous.votes[3]/members[3].become.leader

2021/04/07 11:39:25.332746 trace.go:32: [WARNING] LEADER[ID:test-krypton-0.test-krypton.default.svc.cluster.local:8801, V:12, E:2].candidate.state.machine.exit

2021/04/07 11:39:25.332755 trace.go:32: [WARNING] LEADER[ID:test-krypton-0.test-krypton.default.svc.cluster.local:8801, V:12, E:2].state.init

2021/04/07 11:39:25.332769 trace.go:27: [INFO] LEADER[ID:test-krypton-0.test-krypton.default.svc.cluster.local:8801, V:12, E:2].purge.binlog.start[300000ms]...

2021/04/07 11:39:25.332779 trace.go:27: [INFO] LEADER[ID:test-krypton-0.test-krypton.default.svc.cluster.local:8801, V:12, E:2].check.semi-sync.thread.start[5000ms]...

2021/04/07 11:39:25.332787 trace.go:27: [INFO] LEADER[ID:test-krypton-0.test-krypton.default.svc.cluster.local:8801, V:12, E:2].check.gtid.thread.start[5000ms]...

2021/04/07 11:39:25.332794 trace.go:32: [WARNING] LEADER[ID:test-krypton-0.test-krypton.default.svc.cluster.local:8801, V:12, E:2].async.setting.prepare....

2021/04/07 11:39:25.332829 trace.go:32: [WARNING] LEADER[ID:test-krypton-0.test-krypton.default.svc.cluster.local:8801, V:12, E:2].state.machine.run

2021/04/07 11:39:25.334038 api.go:280: [INFO] mysql.slave.status:&{mysql-bin.000002 154 false No true Yes Slave has read all relay log; waiting for more updates }

2021/04/07 11:39:25.334064 trace.go:32: [WARNING] LEADER[ID:test-krypton-0.test-krypton.default.svc.cluster.local:8801, V:12, E:2].my.gtid.is:{mysql-bin.000002 154 false No true Yes Slave has read all relay log; waiting for more updates }

2021/04/07 11:39:25.334074 trace.go:32: [WARNING] LEADER[ID:test-krypton-0.test-krypton.default.svc.cluster.local:8801, V:12, E:2].1. mysql.WaitUntilAfterGTID.prepare

2021/04/07 11:39:25.392320 trace.go:32: [WARNING] LEADER[ID:test-krypton-0.test-krypton.default.svc.cluster.local:8801, V:12, E:2].mysql.WaitUntilAfterGTID.done

2021/04/07 11:39:25.392348 trace.go:32: [WARNING] LEADER[ID:test-krypton-0.test-krypton.default.svc.cluster.local:8801, V:12, E:2].2. mysql.ChangeToMaster.prepare

2021/04/07 11:39:25.412773 trace.go:32: [WARNING] LEADER[ID:test-krypton-0.test-krypton.default.svc.cluster.local:8801, V:12, E:2].mysql.ChangeToMaster.done

2021/04/07 11:39:25.412829 trace.go:32: [WARNING] LEADER[ID:test-krypton-0.test-krypton.default.svc.cluster.local:8801, V:12, E:2].3. mysql.EnableSemiSyncMaster.prepare

2021/04/07 11:39:25.413856 trace.go:32: [WARNING] LEADER[ID:test-krypton-0.test-krypton.default.svc.cluster.local:8801, V:12, E:2].mysql.EnableSemiSyncMaster.done

2021/04/07 11:39:25.413868 trace.go:32: [WARNING] LEADER[ID:test-krypton-0.test-krypton.default.svc.cluster.local:8801, V:12, E:2].4.mysql.SetSysVars.prepare

2021/04/07 11:39:25.414082 api.go:356: [ERROR] mysql[localhost:3306].SetMasterGlobalSysVar.error[Error 1193: Unknown system variable 'tokudb_fsync_log_period'].var[SET GLOBAL tokudb_fsync_log_period=default]

2021/04/07 11:39:25.414338 api.go:359: [WARNING] mysql[localhost:3306].SetMasterGlobalSysVar[tokudb_fsync_log_period=default;sync_binlog=default;innodb_flush_log_at_trx_commit=default]

2021/04/07 11:39:25.414348 trace.go:32: [WARNING] LEADER[ID:test-krypton-0.test-krypton.default.svc.cluster.local:8801, V:12, E:2].mysql.SetSysVars.done

2021/04/07 11:39:25.414354 trace.go:32: [WARNING] LEADER[ID:test-krypton-0.test-krypton.default.svc.cluster.local:8801, V:12, E:2].5. mysql.SetReadWrite.prepare

2021/04/07 11:39:25.414572 trace.go:32: [WARNING] LEADER[ID:test-krypton-0.test-krypton.default.svc.cluster.local:8801, V:12, E:2].mysql.SetReadWrite.done

2021/04/07 11:39:25.414585 trace.go:32: [WARNING] LEADER[ID:test-krypton-0.test-krypton.default.svc.cluster.local:8801, V:12, E:2].6. start.vip.prepare

2021/04/07 11:39:25.531878 trace.go:32: [WARNING] LEADER[ID:test-krypton-0.test-krypton.default.svc.cluster.local:8801, V:12, E:2].leaderStartShellCommand[[-c /scripts/leader-start.sh]].done

2021/04/07 11:39:25.531905 trace.go:32: [WARNING] LEADER[ID:test-krypton-0.test-krypton.default.svc.cluster.local:8801, V:12, E:2].start.vip.done

2021/04/07 11:39:25.531920 trace.go:32: [WARNING] LEADER[ID:test-krypton-0.test-krypton.default.svc.cluster.local:8801, V:12, E:2].async.setting.all.done....

2021/04/07 11:39:30.333380 api.go:280: [INFO] mysql.slave.status:&{ 0 false false }

2021/04/07 11:39:30.333841 api.go:290: [INFO] mysql.master.status:&{mysql-bin.000002 154 true true 0 }
@andyli029
Copy link
Contributor Author 

/ $ xenoncli cluster status
+------------------------------------------------------------+--------------------------------+--------+---------+--------------------------+---------------------+----------------+------------------------------------------------------------+
|                             ID                             |              Raft              | Mysqld | Monitor |          Backup  |        Mysql        | IO/SQL_RUNNING |                          MyLeader                          |
+------------------------------------------------------------+--------------------------------+--------+---------+--------------------------+---------------------+----------------+------------------------------------------------------------+
| test-krypton-1.test-krypton.default.svc.cluster.local:8801 | [ViewID:11 EpochID:2]@LEADER   | UNKNOW | OFF     | state:[NONE]␤  | [ALIVE] [READWRITE] | [true/true]    | test-krypton-1.test-krypton.default.svc.cluster.local:8801 |
|                                                            |                                |        |         | LastError:  |                     |                |                                                            |
+------------------------------------------------------------+--------------------------------+--------+---------+--------------------------+---------------------+----------------+------------------------------------------------------------+
| test-krypton-0.test-krypton.default.svc.cluster.local:8801 | UNKNOW                         | UNKNOW | UNKNOW  | UNKNOW  | UNKNOW              | UNKNOW         | UNKNOW                                                     |
+------------------------------------------------------------+--------------------------------+--------+---------+--------------------------+---------------------+----------------+------------------------------------------------------------+
| test-krypton-2.test-krypton.default.svc.cluster.local:8801 | [ViewID:11 EpochID:2]@FOLLOWER | UNKNOW | OFF     | state:[NONE]␤  | [ALIVE] [READONLY]  | [true/true]    | test-krypton-1.test-krypton.default.svc.cluster.local:8801 |
|                                                            |                                |        |         | LastError:  |                     |                |                                                            |
+------------------------------------------------------------+--------------------------------+--------+---------+--------------------------+---------------------+----------------+------------------------------------------------------------+

/ $ xenoncli cluster status
+------------------------------------------------------------+--------------------------------+--------+---------+--------------------------+---------------------+----------------+------------------------------------------------------------+
|                             ID                             |              Raft              | Mysqld | Monitor |          Backup  |        Mysql        | IO/SQL_RUNNING |                          MyLeader                          |
+------------------------------------------------------------+--------------------------------+--------+---------+--------------------------+---------------------+----------------+------------------------------------------------------------+
| test-krypton-1.test-krypton.default.svc.cluster.local:8801 | [ViewID:12 EpochID:2]@FOLLOWER | UNKNOW | OFF     | state:[NONE]␤  | [ALIVE] [READONLY]  | [false/true]   | test-krypton-0.test-krypton.default.svc.cluster.local:8801 |
|                                                            |                                |        |         | LastError:  |                     |                |                                                            |
+------------------------------------------------------------+--------------------------------+--------+---------+--------------------------+---------------------+----------------+------------------------------------------------------------+
| test-krypton-0.test-krypton.default.svc.cluster.local:8801 | [ViewID:12 EpochID:2]@LEADER   | UNKNOW | OFF     | state:[NONE]␤  | [ALIVE] [READWRITE] | [true/true]    | test-krypton-0.test-krypton.default.svc.cluster.local:8801 |
|                                                            |                                |        |         | LastError:  |                     |                |                                                            |
+------------------------------------------------------------+--------------------------------+--------+---------+--------------------------+---------------------+----------------+------------------------------------------------------------+
| test-krypton-2.test-krypton.default.svc.cluster.local:8801 | [ViewID:12 EpochID:2]@FOLLOWER | UNKNOW | OFF     | state:[NONE]␤  | [ALIVE] [READONLY]  | [false/true]   | test-krypton-0.test-krypton.default.svc.cluster.local:8801 |
|                                                            |                                |        |         | LastError:  |                     |                |                                                            |
+------------------------------------------------------------+--------------------------------+--------+---------+--------------------------+---------------------+----------------+------------------------------------------------------------+
(3 rows)

@andyli029 andyli029 added the enhancement New feature or request label Apr 8, 2021
@runkecheng
Copy link
Collaborator

The data under pressure measurement conditions:

the old slave ->the new leader

2021/04/08 02:28:10.315779 trace.go:32: [WARNING] FOLLOWER[ID:kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:10, E:2].timeout.and.ping.almost.node.successed.promote.to.candidate

2021/04/08 02:28:10.316665 trace.go:32: [WARNING] CANDIDATE[ID:kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:10, E:2].follower.state.machine.exit

2021/04/08 02:28:10.316681 trace.go:32: [WARNING] CANDIDATE[ID:kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:10, E:2].state.machine.run

2021/04/08 02:28:10.316720 trace.go:32: [WARNING] CANDIDATE[ID:kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].prepare.send.requestvote.to[kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801]

2021/04/08 02:28:10.316855 trace.go:32: [WARNING] CANDIDATE[ID:kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].prepare.send.requestvote.to[kr-test-kryp-1.kr-test-kryp.krypton-deploy.svc.cluster.local:8801]

2021/04/08 02:28:10.318986 api.go:280: [INFO] mysql.slave.status:&{mysql-bin.000002 75963418 false No true Yes 77b1bbdf-d4c8-49a4-97af-8e773a145cbb:1-156 Slave has read all relay log; waiting for more updates }

2021/04/08 02:28:10.319095 trace.go:32: [WARNING] CANDIDATE[ID:kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].send.requestvote.to.peer[kr-test-kryp-1.kr-test-kryp.krypton-deploy.svc.cluster.local:8801].request.gtid[{mysql-bin.000002 75963418 false No true Yes 77b1bbdf-d4c8-49a4-97af-8e773a145cbb:1-156 Slave has read all relay log; waiting for more updates }]

2021/04/08 02:28:10.319398 api.go:280: [INFO] mysql.slave.status:&{mysql-bin.000002 75963418 false No true Yes 77b1bbdf-d4c8-49a4-97af-8e773a145cbb:1-156 Slave has read all relay log; waiting for more updates }

2021/04/08 02:28:10.319438 trace.go:32: [WARNING] CANDIDATE[ID:kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].send.requestvote.to.peer[kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801].request.gtid[{mysql-bin.000002 75963418 false No true Yes 77b1bbdf-d4c8-49a4-97af-8e773a145cbb:1-156 Slave has read all relay log; waiting for more updates }]

2021/04/08 02:28:10.457032 trace.go:32: [WARNING] CANDIDATE[ID:kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].send.requestvote.done.to[kr-test-kryp-1.kr-test-kryp.krypton-deploy.svc.cluster.local:8801]

2021/04/08 02:28:10.559408 trace.go:32: [WARNING] CANDIDATE[ID:kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].send.requestvote.done.to[kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801]

2021/04/08 02:28:10.559495 trace.go:32: [WARNING] CANDIDATE[ID:kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].get.vote.response.from[N:kr-test-kryp-1.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, R:FOLLOWER].rsp.gtid[{mysql-bin.000002 75963418 false No true Yes 77b1bbdf-d4c8-49a4-97af-8e773a145cbb:1-156 77b1bbdf-d4c8-49a4-97af-8e773a145cbb:1-156 Slave has read all relay log; waiting for more updates }].retcode[OK]

2021/04/08 02:28:10.559514 trace.go:27: [INFO] CANDIDATE[ID:kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].get.vote.response.from[N:kr-test-kryp-1.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:10].ok.votegranted[2].majoyrity[2]

2021/04/08 02:28:10.559537 trace.go:32: [WARNING] CANDIDATE[ID:kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].get.vote.response.from[N:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, R:LEADER].rsp.gtid[{mysql-bin.000002 75963418 true true 77b1bbdf-d4c8-49a4-97af-8e773a145cbb:1-156 0 }].retcode[OK]

2021/04/08 02:28:10.559548 trace.go:27: [INFO] CANDIDATE[ID:kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].get.vote.response.from[N:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:10].ok.votegranted[3].majoyrity[2]

2021/04/08 02:28:10.559557 trace.go:32: [WARNING] CANDIDATE[ID:kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].grants.unanimous.votes[3]/members[3].become.leader

2021/04/08 02:28:10.559569 trace.go:32: [WARNING] LEADER[ID:kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].candidate.state.machine.exit

2021/04/08 02:28:10.559580 trace.go:32: [WARNING] LEADER[ID:kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].state.init

2021/04/08 02:28:10.559601 trace.go:27: [INFO] LEADER[ID:kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].purge.binlog.start[300000ms]...

2021/04/08 02:28:10.559612 trace.go:27: [INFO] LEADER[ID:kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].check.semi-sync.thread.start[5000ms]...

2021/04/08 02:28:10.559630 trace.go:27: [INFO] LEADER[ID:kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].check.gtid.thread.start[5000ms]...

2021/04/08 02:28:10.559691 trace.go:32: [WARNING] LEADER[ID:kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].async.setting.prepare....

2021/04/08 02:28:10.559702 trace.go:32: [WARNING] LEADER[ID:kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].state.machine.run

2021/04/08 02:28:10.615697 api.go:280: [INFO] mysql.slave.status:&{mysql-bin.000002 75963418 false No true Yes 77b1bbdf-d4c8-49a4-97af-8e773a145cbb:1-156 Slave has read all relay log; waiting for more updates }

2021/04/08 02:28:10.615767 trace.go:32: [WARNING] LEADER[ID:kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].my.gtid.is:{mysql-bin.000002 75963418 false No true Yes 77b1bbdf-d4c8-49a4-97af-8e773a145cbb:1-156 Slave has read all relay log; waiting for more updates }

2021/04/08 02:28:10.615784 trace.go:32: [WARNING] LEADER[ID:kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].1. mysql.WaitUntilAfterGTID.prepare

2021/04/08 02:28:10.616871 trace.go:32: [WARNING] LEADER[ID:kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].mysql.WaitUntilAfterGTID.done

2021/04/08 02:28:10.616892 trace.go:32: [WARNING] LEADER[ID:kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].2. mysql.ChangeToMaster.prepare

2021/04/08 02:28:10.722097 trace.go:32: [WARNING] LEADER[ID:kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].mysql.ChangeToMaster.done

2021/04/08 02:28:10.722150 trace.go:32: [WARNING] LEADER[ID:kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].3. mysql.EnableSemiSyncMaster.prepare

2021/04/08 02:28:10.723213 trace.go:32: [WARNING] LEADER[ID:kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].mysql.EnableSemiSyncMaster.done

2021/04/08 02:28:10.723408 trace.go:32: [WARNING] LEADER[ID:kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].4.mysql.SetSysVars.prepare

2021/04/08 02:28:10.814124 api.go:356: [ERROR] mysql[localhost:3306].SetMasterGlobalSysVar.error[Error 1193: Unknown system variable 'tokudb_fsync_log_period'].var[SET GLOBAL tokudb_fsync_log_period=default]

2021/04/08 02:28:10.815880 api.go:359: [WARNING] mysql[localhost:3306].SetMasterGlobalSysVar[tokudb_fsync_log_period=default;sync_binlog=default;innodb_flush_log_at_trx_commit=default]

2021/04/08 02:28:10.815908 trace.go:32: [WARNING] LEADER[ID:kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].mysql.SetSysVars.done

2021/04/08 02:28:10.815916 trace.go:32: [WARNING] LEADER[ID:kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].5. mysql.SetReadWrite.prepare

2021/04/08 02:28:10.817642 trace.go:32: [WARNING] LEADER[ID:kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].mysql.SetReadWrite.done

2021/04/08 02:28:10.817664 trace.go:32: [WARNING] LEADER[ID:kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].6. start.vip.prepare

2021/04/08 02:28:10.941368 trace.go:32: [WARNING] LEADER[ID:kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].leaderStartShellCommand[[-c /scripts/leader-start.sh]].done

2021/04/08 02:28:10.941397 trace.go:32: [WARNING] LEADER[ID:kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].start.vip.done

2021/04/08 02:28:10.941411 trace.go:32: [WARNING] LEADER[ID:kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].async.setting.all.done....

2021/04/08 02:28:15.617044 api.go:280: [INFO] mysql.slave.status:&{ 0 false false }

2021/04/08 02:28:15.712740 api.go:290: [INFO] mysql.master.status:&{mysql-bin.000003 75961346 true true 77b1bbdf-d4c8-49a4-97af-8e773a145cbb:1-156 0 }

the old master -> the new slave

2021/04/08 02:28:09.584523 trace.go:37: [ERROR] LEADER[ID:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:10, E:2].send.heartbeat.to.peer[kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801].new.client.error[dial tcp: lookup kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local: no such host]

2021/04/08 02:28:09.584559 trace.go:37: [ERROR] LEADER[ID:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:10, E:2].send.heartbeat.get.rsp[N:, V:0, E:0].error[ErrorRpcCall]

2021/04/08 02:28:10.394993 trace.go:32: [WARNING] LEADER[ID:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:10, E:2].get.voterequest.from[{Raft:{EpochID:2 ViewID:11 Leader: From:kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801 To:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801 State:} Repl:{Master_Host: Master_Port:0 Repl_User: Repl_Password:} GTID:{Master_Log_File:mysql-bin.000002 Read_Master_Log_Pos:75963418 Relay_Master_Log_File: Slave_IO_Running:false Slave_IO_Running_Str:No Slave_SQL_Running:true Slave_SQL_Running_Str:Yes Retrieved_GTID_Set: Executed_GTID_Set:77b1bbdf-d4c8-49a4-97af-8e773a145cbb:1-156 Seconds_Behind_Master: Slave_SQL_Running_State:Slave has read all relay log; waiting for more updates Last_Error: Last_IO_Error: Last_SQL_Error:} Peers:[] IdlePeers:[]}]

2021/04/08 02:28:10.395638 api.go:280: [INFO] mysql.slave.status:&{ 0 false false }

2021/04/08 02:28:10.398659 api.go:290: [INFO] mysql.master.status:&{mysql-bin.000002 75963418 true true 77b1bbdf-d4c8-49a4-97af-8e773a145cbb:1-156 0 }

2021/04/08 02:28:10.398779 api.go:104: [WARNING] mysql.gtid.compare.this[{mysql-bin.000002 75963418 true true 77b1bbdf-d4c8-49a4-97af-8e773a145cbb:1-156 0 }].from[&{mysql-bin.000002 75963418 false No true Yes 77b1bbdf-d4c8-49a4-97af-8e773a145cbb:1-156 Slave has read all relay log; waiting for more updates }]

2021/04/08 02:28:10.398816 trace.go:32: [WARNING] LEADER[ID:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:10, E:2].get.requestvote.from[N:kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].degrade.to.follower

2021/04/08 02:28:10.398824 trace.go:32: [WARNING] LEADER[ID:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:10, E:2].do.updateViewID[FROM:10 TO:11]

2021/04/08 02:28:10.398836 trace.go:32: [WARNING] LEADER[ID:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].degrade.to.follower.stop.the.vip...

2021/04/08 02:28:10.554522 trace.go:32: [WARNING] LEADER[ID:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].leaderStopShellCommand[[-c /scripts/leader-stop.sh]].done

2021/04/08 02:28:10.554552 trace.go:27: [INFO] LEADER[ID:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].check.semi-sync.thread.stop...

2021/04/08 02:28:10.554580 trace.go:27: [INFO] LEADER[ID:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].check.gtid.thread.stop...

2021/04/08 02:28:10.554596 trace.go:32: [WARNING] FOLLOWER[ID:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].leader.state.machine.exit.done

2021/04/08 02:28:10.554603 trace.go:27: [INFO] FOLLOWER[ID:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].start.CheckBrainSplit

2021/04/08 02:28:10.554623 trace.go:32: [WARNING] FOLLOWER[ID:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].state.init

2021/04/08 02:28:10.762086 trace.go:32: [WARNING] FOLLOWER[ID:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].leaderStopShellCommand[[-c /scripts/leader-stop.sh]].done

2021/04/08 02:28:10.762137 trace.go:32: [WARNING] FOLLOWER[ID:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].mysql.waitMysqlDoneAsync.prepare

2021/04/08 02:28:10.762164 trace.go:32: [WARNING] FOLLOWER[ID:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].state.machine.run

2021/04/08 02:28:11.403420 trace.go:32: [WARNING] FOLLOWER[ID:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].mysql.SetReadOnly.done

2021/04/08 02:28:11.404179 api.go:376: [ERROR] mysql[localhost:3306].SetSlaveGlobalSysVar.error[Error 1193: Unknown system variable 'tokudb_fsync_log_period'].var[SET GLOBAL tokudb_fsync_log_period=1000]

2021/04/08 02:28:11.404508 api.go:379: [WARNING] mysql[localhost:3306].SetSlaveGlobalSysVar[tokudb_fsync_log_period=1000;sync_binlog=1000;innodb_flush_log_at_trx_commit=1]

2021/04/08 02:28:11.404618 trace.go:37: [ERROR] FOLLOWER[ID:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].mysql.SetSlaveGlobalSysVar.error[Error 1193: Unknown system variable 'tokudb_fsync_log_period']

2021/04/08 02:28:11.404648 trace.go:32: [WARNING] FOLLOWER[ID:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].mysql.SetSlaveGlobalSysVar.done

2021/04/08 02:28:11.444071 trace.go:32: [WARNING] FOLLOWER[ID:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].prepareAsync.done

2021/04/08 02:28:11.454993 trace.go:37: [ERROR] FOLLOWER[ID:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].mysql.StartSlave.error[Error 1200: The server is not configured as slave; fix in config file or with CHANGE MASTER TO]

2021/04/08 02:28:11.455155 api.go:280: [INFO] mysql.slave.status:&{ 0 false false }

2021/04/08 02:28:11.455343 api.go:280: [INFO] mysql.slave.status:&{ 0 false false }

2021/04/08 02:28:11.455385 api.go:290: [INFO] mysql.master.status:&{mysql-bin.000002 75963418 true true 77b1bbdf-d4c8-49a4-97af-8e773a145cbb:1-156 0 }

2021/04/08 02:28:11.455525 trace.go:32: [WARNING] FOLLOWER[ID:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].init.my.gtid.is:{mysql-bin.000002 75963418 true true 77b1bbdf-d4c8-49a4-97af-8e773a145cbb:1-156 0 }

2021/04/08 02:28:11.459652 api.go:290: [INFO] mysql.master.status:&{mysql-bin.000002 75963418 true true 77b1bbdf-d4c8-49a4-97af-8e773a145cbb:1-156 0 }

2021/04/08 02:28:11.459678 trace.go:32: [WARNING] FOLLOWER[ID:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].get.heartbeat.my.gtid.is:{mysql-bin.000002 75963418 true true 77b1bbdf-d4c8-49a4-97af-8e773a145cbb:1-156 0 }

2021/04/08 02:28:11.460190 mysql.go:137: [INFO] mysql.get.local.uuid:[77b1bbdf-d4c8-49a4-97af-8e773a145cbb]

2021/04/08 02:28:11.460369 trace.go:32: [WARNING] FOLLOWER[ID:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].get.heartbeat.from[N:kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].change.mysql.master

2021/04/08 02:28:11.469946 trace.go:32: [WARNING] FOLLOWER[ID:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].get.heartbeat.change.to.the.new.master[kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801].successed

2021/04/08 02:28:15.554769 trace.go:32: [WARNING] FOLLOWER[ID:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].ping.responses[1].is.less.than.half.maybe.brain.split

2021/04/08 02:28:15.556713 trace.go:32: [WARNING] FOLLOWER[ID:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].ping.responses[2].is.greater.than.half.again

2021/04/08 02:28:20.555951 trace.go:37: [ERROR] FOLLOWER[ID:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].send.ping.to.peer[kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801].new.client.error[dial tcp: lookup kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local: no such host]

2021/04/08 02:28:20.744827 trace.go:32: [WARNING] FOLLOWER[ID:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].ping.responses[2].is.greater.than.half.again

2021/04/08 02:28:25.643842 trace.go:37: [ERROR] FOLLOWER[ID:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].send.ping.to.peer[kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801].new.client.error[dial tcp: lookup kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local: no such host]

2021/04/08 02:28:25.646335 trace.go:32: [WARNING] FOLLOWER[ID:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:11, E:2].ping.responses[2].is.greater.than.half.again

2021/04/08 02:34:51.519274 api.go:280: [INFO] mysql.slave.status:&{mysql-bin.000003 75961346 true Yes true Yes 77b1bbdf-d4c8-49a4-97af-8e773a145cbb:1-156 0 Slave has read all relay log; waiting for more updates }

2021/04/08 02:35:02.823892 api.go:280: [INFO] mysql.slave.status:&{mysql-bin.000003 75961346 true Yes true Yes 77b1bbdf-d4c8-49a4-97af-8e773a145cbb:1-156 0 Slave has read all relay log; waiting for more updates }

@runkecheng
Copy link
Collaborator

Write-only on the master node, xenon log of the master:

2021/04/08 05:56:15.845251 api.go:280: [INFO] mysql.slave.status:&{ 0 false false }

2021/04/08 05:56:15.848668 api.go:290: [INFO] mysql.master.status:&{mysql-bin.000003 305416148 true true 37f1ae89-b911-4eb3-8a22-275f255f20a0:1-93762,

77b1bbdf-d4c8-49a4-97af-8e773a145cbb:1-541995 0 }

2021/04/08 05:56:20.150842 trace.go:37: [ERROR] LEADER[ID:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:47, E:2].send.heartbeat.to.peer[kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801].new.client.error[dial tcp 10.10.128.145:8801: connect: connection refused]

2021/04/08 05:56:20.150939 trace.go:37: [ERROR] LEADER[ID:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:47, E:2].send.heartbeat.get.rsp[N:, V:0, E:0].error[ErrorRpcCall]

2021/04/08 05:56:20.844015 api.go:280: [INFO] mysql.slave.status:&{ 0 false false }

2021/04/08 05:56:20.852424 api.go:290: [INFO] mysql.master.status:&{mysql-bin.000003 308474142 true true 37f1ae89-b911-4eb3-8a22-275f255f20a0:1-93762,

77b1bbdf-d4c8-49a4-97af-8e773a145cbb:1-543707 0 }

2021/04/08 05:56:22.149362 trace.go:32: [WARNING] LEADER[ID:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:47, E:2].heartbeat.acks.granted[2].less.than.members[3].for.the.first.time

2021/04/08 05:56:22.149454 trace.go:32: [WARNING] LEADER[ID:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:47, E:2].do.updateViewID[FROM:47 TO:49]

2021/04/08 05:56:22.243773 trace.go:37: [ERROR] LEADER[ID:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:49, E:2].send.heartbeat.to.peer[kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801].new.client.error[dial tcp 10.10.128.145:8801: connect: connection refused]

2021/04/08 05:56:22.243805 trace.go:37: [ERROR] LEADER[ID:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:49, E:2].send.heartbeat.get.rsp[N:, V:0, E:0].error[ErrorRpcCall]

2021/04/08 05:56:25.845914 api.go:280: [INFO] mysql.slave.status:&{ 0 false false }

2021/04/08 05:56:25.951643 api.go:290: [INFO] mysql.master.status:&{mysql-bin.000003 311605107 true true 37f1ae89-b911-4eb3-8a22-275f255f20a0:1-93762,

77b1bbdf-d4c8-49a4-97af-8e773a145cbb:1-545528 0 }

2021/04/08 05:56:26.150815 trace.go:32: [WARNING] LEADER[ID:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:49, E:2].heartbeat.acks.granted[3].equals.members[3].again

2021/04/08 05:56:30.847498 api.go:280: [INFO] mysql.slave.status:&{ 0 false false }

2021/04/08 05:56:30.946116 api.go:290: [INFO] mysql.master.status:&{mysql-bin.000003 314289761 true true 37f1ae89-b911-4eb3-8a22-275f255f20a0:1-93762,

77b1bbdf-d4c8-49a4-97af-8e773a145cbb:1-547219 0 }

xenon log of the slave:

2021/04/08 05:56:15.845251 api.go:280: [INFO] mysql.slave.status:&{ 0 false false }

2021/04/08 05:56:15.848668 api.go:290: [INFO] mysql.master.status:&{mysql-bin.000003 305416148 true true 37f1ae89-b911-4eb3-8a22-275f255f20a0:1-93762,

77b1bbdf-d4c8-49a4-97af-8e773a145cbb:1-541995 0 }

2021/04/08 05:56:20.150842 trace.go:37: [ERROR] LEADER[ID:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:47, E:2].send.heartbeat.to.peer[kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801].new.client.error[dial tcp 10.10.128.145:8801: connect: connection refused]

2021/04/08 05:56:20.150939 trace.go:37: [ERROR] LEADER[ID:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:47, E:2].send.heartbeat.get.rsp[N:, V:0, E:0].error[ErrorRpcCall]

2021/04/08 05:56:20.844015 api.go:280: [INFO] mysql.slave.status:&{ 0 false false }

2021/04/08 05:56:20.852424 api.go:290: [INFO] mysql.master.status:&{mysql-bin.000003 308474142 true true 37f1ae89-b911-4eb3-8a22-275f255f20a0:1-93762,

77b1bbdf-d4c8-49a4-97af-8e773a145cbb:1-543707 0 }

2021/04/08 05:56:22.149362 trace.go:32: [WARNING] LEADER[ID:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:47, E:2].heartbeat.acks.granted[2].less.than.members[3].for.the.first.time

2021/04/08 05:56:22.149454 trace.go:32: [WARNING] LEADER[ID:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:47, E:2].do.updateViewID[FROM:47 TO:49]

2021/04/08 05:56:22.243773 trace.go:37: [ERROR] LEADER[ID:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:49, E:2].send.heartbeat.to.peer[kr-test-kryp-0.kr-test-kryp.krypton-deploy.svc.cluster.local:8801].new.client.error[dial tcp 10.10.128.145:8801: connect: connection refused]

2021/04/08 05:56:22.243805 trace.go:37: [ERROR] LEADER[ID:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:49, E:2].send.heartbeat.get.rsp[N:, V:0, E:0].error[ErrorRpcCall]

2021/04/08 05:56:25.845914 api.go:280: [INFO] mysql.slave.status:&{ 0 false false }

2021/04/08 05:56:25.951643 api.go:290: [INFO] mysql.master.status:&{mysql-bin.000003 311605107 true true 37f1ae89-b911-4eb3-8a22-275f255f20a0:1-93762,

77b1bbdf-d4c8-49a4-97af-8e773a145cbb:1-545528 0 }

2021/04/08 05:56:26.150815 trace.go:32: [WARNING] LEADER[ID:kr-test-kryp-2.kr-test-kryp.krypton-deploy.svc.cluster.local:8801, V:49, E:2].heartbeat.acks.granted[3].equals.members[3].again

2021/04/08 05:56:30.847498 api.go:280: [INFO] mysql.slave.status:&{ 0 false false }

2021/04/08 05:56:30.946116 api.go:290: [INFO] mysql.master.status:&{mysql-bin.000003 314289761 true true 37f1ae89-b911-4eb3-8a22-275f255f20a0:1-93762,

77b1bbdf-d4c8-49a4-97af-8e773a145cbb:1-547219 0 }

@andyli029
Copy link
Contributor Author

@runkecheng

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@andyli029 andyli029

@runkecheng runkecheng

Labels
enhancement New feature or request
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@andyli029 @runkecheng