failover过程

完整日志如下(GTID模式)

  1. Mon Jun 10 11:25:51 2019 - [warning] Got error on MySQL select ping: 1053 (Server shutdown in progress)
  2. Mon Jun 10 11:25:51 2019 - [info] Executing SSH check script: exit 0
  3. Mon Jun 10 11:25:51 2019 - [warning] HealthCheck: SSH to db1 is NOT reachable.
  4. Mon Jun 10 11:25:52 2019 - [warning] Got error on MySQL connect: 2003 (Can't connect to MySQL server on '10.100.64.119' (111))
  5. Mon Jun 10 11:25:52 2019 - [warning] Connection failed 2 time(s)..
  6. Mon Jun 10 11:25:53 2019 - [warning] Got error on MySQL connect: 2003 (Can't connect to MySQL server on '10.100.64.119' (111))
  7. Mon Jun 10 11:25:53 2019 - [warning] Connection failed 3 time(s)..
  8. Mon Jun 10 11:25:54 2019 - [warning] Got error on MySQL connect: 2003 (Can't connect to MySQL server on '10.100.64.119' (111))
  9. Mon Jun 10 11:25:54 2019 - [warning] Connection failed 4 time(s)..
  10. Mon Jun 10 11:25:54 2019 - [warning] Master is not reachable from health checker!
  11. Mon Jun 10 11:25:54 2019 - [warning] Master db1(10.100.64.119:3306) is not reachable!
  12. Mon Jun 10 11:25:54 2019 - [warning] SSH is NOT reachable.
  13. Mon Jun 10 11:25:54 2019 - [info] Connecting to a master server failed. Reading configuration file /etc/masterha/masterha_default.conf and /etc/masterha/app1.conf again, and trying to connect to all servers to check server status..
  14. Mon Jun 10 11:25:54 2019 - [info] Reading default configuration from /etc/masterha/masterha_default.conf..
  15. Mon Jun 10 11:25:54 2019 - [info] Reading application default configuration from /etc/masterha/app1.conf..
  16. Mon Jun 10 11:25:54 2019 - [info] Reading server configuration from /etc/masterha/app1.conf..
  17. Mon Jun 10 11:25:55 2019 - [info] GTID failover mode = 1
  18. Mon Jun 10 11:25:55 2019 - [info] Dead Servers:
  19. Mon Jun 10 11:25:55 2019 - [info]   db1(10.100.64.119:3306)
  20. Mon Jun 10 11:25:55 2019 - [info] Alive Servers:
  21. Mon Jun 10 11:25:55 2019 - [info]   db2(10.100.64.120:3306)
  22. Mon Jun 10 11:25:55 2019 - [info]   db3(10.100.64.121:3306)
  23. Mon Jun 10 11:25:55 2019 - [info] Alive Slaves:
  24. Mon Jun 10 11:25:55 2019 - [info]   db2(10.100.64.120:3306)  Version=5.7.23-log (oldest major version between slaves) log-bin:enabled
  25. Mon Jun 10 11:25:55 2019 - [info]     GTID ON
  26. Mon Jun 10 11:25:55 2019 - [info]     Replicating from 10.100.64.119(10.100.64.119:3306)
  27. Mon Jun 10 11:25:55 2019 - [info]     Primary candidate for the new Master (candidate_master is set)
  28. Mon Jun 10 11:25:55 2019 - [info]   db3(10.100.64.121:3306)  Version=5.7.23-log (oldest major version between slaves) log-bin:enabled
  29. Mon Jun 10 11:25:55 2019 - [info]     GTID ON
  30. Mon Jun 10 11:25:55 2019 - [info]     Replicating from 10.100.64.119(10.100.64.119:3306)
  31. Mon Jun 10 11:25:55 2019 - [info]     Primary candidate for the new Master (candidate_master is set)
  32. Mon Jun 10 11:25:55 2019 - [info] Checking slave configurations..
  33. Mon Jun 10 11:25:55 2019 - [info]  read_only=1 is not set on slave db2(10.100.64.120:3306).
  34. Mon Jun 10 11:25:55 2019 - [info]  read_only=1 is not set on slave db3(10.100.64.121:3306).
  35. Mon Jun 10 11:25:55 2019 - [info] Checking replication filtering settings..
  36. Mon Jun 10 11:25:55 2019 - [info]  Replication filtering check ok.
  37. Mon Jun 10 11:25:55 2019 - [info] Master is down!
  38. Mon Jun 10 11:25:55 2019 - [info] Terminating monitoring script.
  39. Mon Jun 10 11:25:55 2019 - [info] Got exit code 20 (Master dead).
  40. Mon Jun 10 11:25:55 2019 - [info] MHA::MasterFailover version 0.58.
  41. Mon Jun 10 11:25:55 2019 - [info] Starting master failover.
  42. Mon Jun 10 11:25:55 2019 - [info] 
  43. Mon Jun 10 11:25:55 2019 - [info] * Phase 1: Configuration Check Phase..
  44. Mon Jun 10 11:25:55 2019 - [info] 
  45. Mon Jun 10 11:25:56 2019 - [info] GTID failover mode = 1
  46. Mon Jun 10 11:25:56 2019 - [info] Dead Servers:
  47. Mon Jun 10 11:25:56 2019 - [info]   db1(10.100.64.119:3306)
  48. Mon Jun 10 11:25:56 2019 - [info] Checking master reachability via MySQL(double check)...
  49. Mon Jun 10 11:25:56 2019 - [info]  ok.
  50. Mon Jun 10 11:25:56 2019 - [info] Alive Servers:
  51. Mon Jun 10 11:25:56 2019 - [info]   db2(10.100.64.120:3306)
  52. Mon Jun 10 11:25:56 2019 - [info]   db3(10.100.64.121:3306)
  53. Mon Jun 10 11:25:56 2019 - [info] Alive Slaves:
  54. Mon Jun 10 11:25:56 2019 - [info]   db2(10.100.64.120:3306)  Version=5.7.23-log (oldest major version between slaves) log-bin:enabled
  55. Mon Jun 10 11:25:56 2019 - [info]     GTID ON
  56. Mon Jun 10 11:25:56 2019 - [info]     Replicating from 10.100.64.119(10.100.64.119:3306)
  57. Mon Jun 10 11:25:56 2019 - [info]     Primary candidate for the new Master (candidate_master is set)
  58. Mon Jun 10 11:25:56 2019 - [info]   db3(10.100.64.121:3306)  Version=5.7.23-log (oldest major version between slaves) log-bin:enabled
  59. Mon Jun 10 11:25:56 2019 - [info]     GTID ON
  60. Mon Jun 10 11:25:56 2019 - [info]     Replicating from 10.100.64.119(10.100.64.119:3306)
  61. Mon Jun 10 11:25:56 2019 - [info]     Primary candidate for the new Master (candidate_master is set)
  62. Mon Jun 10 11:25:56 2019 - [info] Starting GTID based failover.
  63. Mon Jun 10 11:25:56 2019 - [info] 
  64. Mon Jun 10 11:25:56 2019 - [info] ** Phase 1: Configuration Check Phase completed.
  65. Mon Jun 10 11:25:56 2019 - [info] 
  66. Mon Jun 10 11:25:56 2019 - [info] * Phase 2: Dead Master Shutdown Phase..
  67. Mon Jun 10 11:25:56 2019 - [info] 
  68. Mon Jun 10 11:25:56 2019 - [info] Forcing shutdown so that applications never connect to the current master..
  69. Mon Jun 10 11:25:56 2019 - [info] Executing master IP deactivation script:
  70. Mon Jun 10 11:25:56 2019 - [info]   /etc/masterha/master_ip_failover --orig_master_host=db1 --orig_master_ip=10.100.64.119 --orig_master_port=3306 --command=stop  --orig_master_ssh_port=52000
  71. drop vip from original master
  72. ssh: connect to host db1 port 52000: Connection refused
  73. Mon Jun 10 11:25:59 2019 - [info]  done.
  74. Mon Jun 10 11:25:59 2019 - [warning] shutdown_script is not set. Skipping explicit shutting down of the dead master.
  75. Mon Jun 10 11:25:59 2019 - [info] * Phase 2: Dead Master Shutdown Phase completed.
  76. Mon Jun 10 11:25:59 2019 - [info] 
  77. Mon Jun 10 11:25:59 2019 - [info] * Phase 3: Master Recovery Phase..
  78. Mon Jun 10 11:25:59 2019 - [info] 
  79. Mon Jun 10 11:25:59 2019 - [info] * Phase 3.1: Getting Latest Slaves Phase..
  80. Mon Jun 10 11:25:59 2019 - [info] 
  81. Mon Jun 10 11:25:59 2019 - [info] The latest binary log file/position on all slaves is mysql-bin.000037:194
  82. Mon Jun 10 11:25:59 2019 - [info] Latest slaves (Slaves that received relay log files to the latest):
  83. Mon Jun 10 11:25:59 2019 - [info]   db2(10.100.64.120:3306)  Version=5.7.23-log (oldest major version between slaves) log-bin:enabled
  84. Mon Jun 10 11:25:59 2019 - [info]     GTID ON
  85. Mon Jun 10 11:25:59 2019 - [info]     Replicating from 10.100.64.119(10.100.64.119:3306)
  86. Mon Jun 10 11:25:59 2019 - [info]     Primary candidate for the new Master (candidate_master is set)
  87. Mon Jun 10 11:25:59 2019 - [info]   db3(10.100.64.121:3306)  Version=5.7.23-log (oldest major version between slaves) log-bin:enabled
  88. Mon Jun 10 11:25:59 2019 - [info]     GTID ON
  89. Mon Jun 10 11:25:59 2019 - [info]     Replicating from 10.100.64.119(10.100.64.119:3306)
  90. Mon Jun 10 11:25:59 2019 - [info]     Primary candidate for the new Master (candidate_master is set)
  91. Mon Jun 10 11:25:59 2019 - [info] The oldest binary log file/position on all slaves is mysql-bin.000037:194
  92. Mon Jun 10 11:25:59 2019 - [info] Oldest slaves:
  93. Mon Jun 10 11:25:59 2019 - [info]   db2(10.100.64.120:3306)  Version=5.7.23-log (oldest major version between slaves) log-bin:enabled
  94. Mon Jun 10 11:25:59 2019 - [info]     GTID ON
  95. Mon Jun 10 11:25:59 2019 - [info]     Replicating from 10.100.64.119(10.100.64.119:3306)
  96. Mon Jun 10 11:25:59 2019 - [info]     Primary candidate for the new Master (candidate_master is set)
  97. Mon Jun 10 11:25:59 2019 - [info]   db3(10.100.64.121:3306)  Version=5.7.23-log (oldest major version between slaves) log-bin:enabled
  98. Mon Jun 10 11:25:59 2019 - [info]     GTID ON
  99. Mon Jun 10 11:25:59 2019 - [info]     Replicating from 10.100.64.119(10.100.64.119:3306)
  100. Mon Jun 10 11:25:59 2019 - [info]     Primary candidate for the new Master (candidate_master is set)
  101. Mon Jun 10 11:25:59 2019 - [info] 
  102. Mon Jun 10 11:25:59 2019 - [info] * Phase 3.3: Determining New Master Phase..
  103. Mon Jun 10 11:25:59 2019 - [info] 
  104. Mon Jun 10 11:25:59 2019 - [info] Searching new master from slaves..
  105. Mon Jun 10 11:25:59 2019 - [info]  Candidate masters from the configuration file:
  106. Mon Jun 10 11:25:59 2019 - [info]   db2(10.100.64.120:3306)  Version=5.7.23-log (oldest major version between slaves) log-bin:enabled
  107. Mon Jun 10 11:25:59 2019 - [info]     GTID ON
  108. Mon Jun 10 11:25:59 2019 - [info]     Replicating from 10.100.64.119(10.100.64.119:3306)
  109. Mon Jun 10 11:25:59 2019 - [info]     Primary candidate for the new Master (candidate_master is set)
  110. Mon Jun 10 11:25:59 2019 - [info]   db3(10.100.64.121:3306)  Version=5.7.23-log (oldest major version between slaves) log-bin:enabled
  111. Mon Jun 10 11:25:59 2019 - [info]     GTID ON
  112. Mon Jun 10 11:25:59 2019 - [info]     Replicating from 10.100.64.119(10.100.64.119:3306)
  113. Mon Jun 10 11:25:59 2019 - [info]     Primary candidate for the new Master (candidate_master is set)
  114. Mon Jun 10 11:25:59 2019 - [info]  Non-candidate masters:
  115. Mon Jun 10 11:25:59 2019 - [info]  Searching from candidate_master slaves which have received the latest relay log events..
  116. Mon Jun 10 11:25:59 2019 - [info] New master is db2(10.100.64.120:3306)
  117. Mon Jun 10 11:25:59 2019 - [info] Starting master failover..
  118. Mon Jun 10 11:25:59 2019 - [info] 
  119. From:
  120. db1(10.100.64.119:3306) (current master)
  121.  +--db2(10.100.64.120:3306)
  122.  +--db3(10.100.64.121:3306)
  124. To:
  125. db2(10.100.64.120:3306) (new master)
  126.  +--db3(10.100.64.121:3306)
  127. Mon Jun 10 11:25:59 2019 - [info] 
  128. Mon Jun 10 11:25:59 2019 - [info] * Phase 3.3: New Master Recovery Phase..
  129. Mon Jun 10 11:25:59 2019 - [info] 
  130. Mon Jun 10 11:25:59 2019 - [info]  Waiting all logs to be applied.. 
  131. Mon Jun 10 11:25:59 2019 - [info]   done.
  132. Mon Jun 10 11:25:59 2019 - [info] Getting new master's binlog name and position..
  133. Mon Jun 10 11:25:59 2019 - [info]  mysql-bin.000032:194
  134. Mon Jun 10 11:25:59 2019 - [info]  All other slaves should start replication from here. Statement should be: CHANGE MASTER TO MASTER_HOST='db2 or 10.100.64.120', MASTER_PORT=3306, MASTER_AUTO_POSITION=1, MASTER_USER='repl', MASTER_PASSWORD='xxx';
  135. Mon Jun 10 11:25:59 2019 - [info] Master Recovery succeeded. File:Pos:Exec_Gtid_Set: mysql-bin.000032, 194, 479dbc89-e31e-11e8-83eb-005056a8803c:1-696587
  136. Mon Jun 10 11:25:59 2019 - [info] Executing master IP activate script:
  137. Mon Jun 10 11:25:59 2019 - [info]   /etc/masterha/master_ip_failover --command=start --ssh_user=root --orig_master_host=db1 --orig_master_ip=10.100.64.119 --orig_master_port=3306 --new_master_host=db2 --new_master_ip=10.100.64.120 --new_master_port=3306 --new_master_user='xucl'  --orig_master_ssh_port=52000  --new_master_ssh_port=52000 --new_master_password=xxx
  138. Set read_only=0 on the new master.
  139. add vip to new master
  140. Warning: Permanently added '[db2]:52000' (ECDSA) to the list of known hosts.
  141. Mon Jun 10 11:25:59 2019 - [info]  OK.
  142. Mon Jun 10 11:25:59 2019 - [info] ** Finished master recovery successfully.
  143. Mon Jun 10 11:25:59 2019 - [info] * Phase 3: Master Recovery Phase completed.
  144. Mon Jun 10 11:25:59 2019 - [info] 
  145. Mon Jun 10 11:25:59 2019 - [info] * Phase 4: Slaves Recovery Phase..
  146. Mon Jun 10 11:25:59 2019 - [info] 
  147. Mon Jun 10 11:25:59 2019 - [info] 
  148. Mon Jun 10 11:25:59 2019 - [info] * Phase 4.1: Starting Slaves in parallel..
  149. Mon Jun 10 11:25:59 2019 - [info] 
  150. Mon Jun 10 11:25:59 2019 - [info] -- Slave recovery on host db3(10.100.64.121:3306) started, pid: 2886. Check tmp log /var/log/masterha/app1/db3_3306_20190610112555.log if it takes time..
  151. Mon Jun 10 11:26:00 2019 - [info] 
  152. Mon Jun 10 11:26:00 2019 - [info] Log messages from db3 ...
  153. Mon Jun 10 11:26:00 2019 - [info] 
  154. Mon Jun 10 11:25:59 2019 - [info]  Resetting slave db3(10.100.64.121:3306) and starting replication from the new master db2(10.100.64.120:3306)..
  155. Mon Jun 10 11:25:59 2019 - [info]  Executed CHANGE MASTER.
  156. Mon Jun 10 11:25:59 2019 - [info]  Slave started.
  157. Mon Jun 10 11:25:59 2019 - [info]  gtid_wait(479dbc89-e31e-11e8-83eb-005056a8803c:1-696587) completed on db3(10.100.64.121:3306). Executed 0 events.
  158. Mon Jun 10 11:26:00 2019 - [info] End of log messages from db3.
  159. Mon Jun 10 11:26:00 2019 - [info] -- Slave on host db3(10.100.64.121:3306) started.
  160. Mon Jun 10 11:26:00 2019 - [info] All new slave servers recovered successfully.
  161. Mon Jun 10 11:26:00 2019 - [info] 
  162. Mon Jun 10 11:26:00 2019 - [info] * Phase 5: New master cleanup phase..
  163. Mon Jun 10 11:26:00 2019 - [info] 
  164. Mon Jun 10 11:26:00 2019 - [info] Resetting slave info on the new master..
  165. Mon Jun 10 11:26:00 2019 - [info]  db2: Resetting slave info succeeded.
  166. Mon Jun 10 11:26:00 2019 - [info] Master failover to db2(10.100.64.120:3306) completed successfully.
  167. Mon Jun 10 11:26:00 2019 - [info] 
  169. ----- Failover Report -----
  171. app1: MySQL Master failover db1(10.100.64.119:3306) to db2(10.100.64.120:3306) succeeded
  173. Master db1(10.100.64.119:3306) is down!
  175. Check MHA Manager logs at manager:/var/log/masterha/app1/app1.log for details.
  177. Started automated(non-interactive) failover.
  178. Invalidated master IP address on db1(10.100.64.119:3306)
  179. Selected db2(10.100.64.120:3306) as a new master.
  180. db2(10.100.64.120:3306): OK: Applying all logs succeeded.
  181. db2(10.100.64.120:3306): OK: Activated master IP address.
  182. db3(10.100.64.121:3306): OK: Slave started, replicating from db2(10.100.64.120:3306)
  183. db2(10.100.64.120:3306): Resetting slave info succeeded.
  184. Master failover to db2(10.100.64.120:3306) completed successfully.

从日志上我们可以做一下分解、切割

Phase 1: Configuration Check Phase..

  1. Mon Jun 10 11:25:56 2019 - [info] GTID failover mode = 1
  2. Mon Jun 10 11:25:56 2019 - [info] Dead Servers:
  3. Mon Jun 10 11:25:56 2019 - [info]   db1(10.100.64.119:3306)
  4. Mon Jun 10 11:25:56 2019 - [info] Checking master reachability via MySQL(double check)...
  5. Mon Jun 10 11:25:56 2019 - [info]  ok.
  6. Mon Jun 10 11:25:56 2019 - [info] Alive Servers:
  7. Mon Jun 10 11:25:56 2019 - [info]   db2(10.100.64.120:3306)
  8. Mon Jun 10 11:25:56 2019 - [info]   db3(10.100.64.121:3306)
  9. Mon Jun 10 11:25:56 2019 - [info] Alive Slaves:
  10. Mon Jun 10 11:25:56 2019 - [info]   db2(10.100.64.120:3306)  Version=5.7.23-log (oldest major version between slaves) log-bin:enabled
  11. Mon Jun 10 11:25:56 2019 - [info]     GTID ON
  12. Mon Jun 10 11:25:56 2019 - [info]     Replicating from 10.100.64.119(10.100.64.119:3306)
  13. Mon Jun 10 11:25:56 2019 - [info]     Primary candidate for the new Master (candidate_master is set)
  14. Mon Jun 10 11:25:56 2019 - [info]   db3(10.100.64.121:3306)  Version=5.7.23-log (oldest major version between slaves) log-bin:enabled
  15. Mon Jun 10 11:25:56 2019 - [info]     GTID ON
  16. Mon Jun 10 11:25:56 2019 - [info]     Replicating from 10.100.64.119(10.100.64.119:3306)
  17. Mon Jun 10 11:25:56 2019 - [info]     Primary candidate for the new Master (candidate_master is set)

该阶段主要做的是：

  • 检查failover模式（这里是基于GTID的failover）
  • 检查dead master（double check）
  • 检查alive servers，并检查每个节点信息（GTID_MODE、从哪里复制、是否是candidate_master、read_only、replication filter）

Phase 2: Dead Master Shutdown Phase..

  1. Mon Jun 10 11:25:56 2019 - [info] * Phase 2: Dead Master Shutdown Phase..
  2. Mon Jun 10 11:25:56 2019 - [info] 
  3. Mon Jun 10 11:25:56 2019 - [info] Forcing shutdown so that applications never connect to the current master..
  4. Mon Jun 10 11:25:56 2019 - [info] Executing master IP deactivation script:
  5. Mon Jun 10 11:25:56 2019 - [info]   /etc/masterha/master_ip_failover --orig_master_host=db1 --orig_master_ip=10.100.64.119 --orig_master_port=3306 --command=stop  --orig_master_ssh_port=52000
  6. drop vip from original master
  7. ssh: connect to host db1 port 52000: Connection refused
  8. Mon Jun 10 11:25:59 2019 - [info]  done.
  9. Mon Jun 10 11:25:59 2019 - [warning] shutdown_script is not set. Skipping explicit shutting down of the dead master.
  10. Mon Jun 10 11:25:59 2019 - [info] * Phase 2: Dead Master Shutdown Phase completed.
  1. /etc/masterha/master_ip_failover --orig_master_host=db1 --orig_master_ip=10.100.64.119 --orig_master_port=3306 --command=stop  --orig_master_ssh_port=52000

调用master_ip_failover脚本，调用stop命令，我们再看下调用stop命令是进行了什么操作

  1. if ( $command eq "stop" || $command eq "stopssh" ) {
  2.     # $orig_master_host, $orig_master_ip, $orig_master_port are passed.
  3.     # If you manage master ip address at global catalog database,
  4.     # invalidate orig_master_ip here.
  5.     &drop_vip();
  6.     my $exit_code = 1;
  7.     eval {
  9.       # updating global catalog, etc
  10.       $exit_code = 0;
  11.     };
  12.     if ($@) {
  13.       warn "Got Error: $@\n";
  14.       exit $exit_code;
  15.     }
  16.     exit $exit_code;
  17.   }

实际上，就是去原先的master执行了删除vip的动作，从我们的日志上看到的是，因为原先的server服务器无法ssh上去，因此也无法执行drop动作

Phase 3: Master Recovery Phase..

  1. Mon Jun 10 11:25:59 2019 - [info] * Phase 3: Master Recovery Phase..
  2. Mon Jun 10 11:25:59 2019 - [info] 
  3. Mon Jun 10 11:25:59 2019 - [info] * Phase 3.1: Getting Latest Slaves Phase..
  4. Mon Jun 10 11:25:59 2019 - [info] 
  5. Mon Jun 10 11:25:59 2019 - [info] The latest binary log file/position on all slaves is mysql-bin.000037:194
  6. Mon Jun 10 11:25:59 2019 - [info] Latest slaves (Slaves that received relay log files to the latest):
  7. Mon Jun 10 11:25:59 2019 - [info]   db2(10.100.64.120:3306)  Version=5.7.23-log (oldest major version between slaves) log-bin:enabled
  8. Mon Jun 10 11:25:59 2019 - [info]     GTID ON
  9. Mon Jun 10 11:25:59 2019 - [info]     Replicating from 10.100.64.119(10.100.64.119:3306)
  10. Mon Jun 10 11:25:59 2019 - [info]     Primary candidate for the new Master (candidate_master is set)
  11. Mon Jun 10 11:25:59 2019 - [info]   db3(10.100.64.121:3306)  Version=5.7.23-log (oldest major version between slaves) log-bin:enabled
  12. Mon Jun 10 11:25:59 2019 - [info]     GTID ON
  13. Mon Jun 10 11:25:59 2019 - [info]     Replicating from 10.100.64.119(10.100.64.119:3306)
  14. Mon Jun 10 11:25:59 2019 - [info]     Primary candidate for the new Master (candidate_master is set)
  15. Mon Jun 10 11:25:59 2019 - [info] The oldest binary log file/position on all slaves is mysql-bin.000037:194
  16. Mon Jun 10 11:25:59 2019 - [info] Oldest slaves:
  17. Mon Jun 10 11:25:59 2019 - [info]   db2(10.100.64.120:3306)  Version=5.7.23-log (oldest major version between slaves) log-bin:enabled
  18. Mon Jun 10 11:25:59 2019 - [info]     GTID ON
  19. Mon Jun 10 11:25:59 2019 - [info]     Replicating from 10.100.64.119(10.100.64.119:3306)
  20. Mon Jun 10 11:25:59 2019 - [info]     Primary candidate for the new Master (candidate_master is set)
  21. Mon Jun 10 11:25:59 2019 - [info]   db3(10.100.64.121:3306)  Version=5.7.23-log (oldest major version between slaves) log-bin:enabled
  22. Mon Jun 10 11:25:59 2019 - [info]     GTID ON
  23. Mon Jun 10 11:25:59 2019 - [info]     Replicating from 10.100.64.119(10.100.64.119:3306)
  24. Mon Jun 10 11:25:59 2019 - [info]     Primary candidate for the new Master (candidate_master is set)
  25. Mon Jun 10 11:25:59 2019 - [info] 
  26. Mon Jun 10 11:25:59 2019 - [info] * Phase 3.3: Determining New Master Phase..
  27. Mon Jun 10 11:25:59 2019 - [info] 
  28. Mon Jun 10 11:25:59 2019 - [info] Searching new master from slaves..
  29. Mon Jun 10 11:25:59 2019 - [info]  Candidate masters from the configuration file:
  30. Mon Jun 10 11:25:59 2019 - [info]   db2(10.100.64.120:3306)  Version=5.7.23-log (oldest major version between slaves) log-bin:enabled
  31. Mon Jun 10 11:25:59 2019 - [info]     GTID ON
  32. Mon Jun 10 11:25:59 2019 - [info]     Replicating from 10.100.64.119(10.100.64.119:3306)
  33. Mon Jun 10 11:25:59 2019 - [info]     Primary candidate for the new Master (candidate_master is set)
  34. Mon Jun 10 11:25:59 2019 - [info]   db3(10.100.64.121:3306)  Version=5.7.23-log (oldest major version between slaves) log-bin:enabled
  35. Mon Jun 10 11:25:59 2019 - [info]     GTID ON
  36. Mon Jun 10 11:25:59 2019 - [info]     Replicating from 10.100.64.119(10.100.64.119:3306)
  37. Mon Jun 10 11:25:59 2019 - [info]     Primary candidate for the new Master (candidate_master is set)
  38. Mon Jun 10 11:25:59 2019 - [info]  Non-candidate masters:
  39. Mon Jun 10 11:25:59 2019 - [info]  Searching from candidate_master slaves which have received the latest relay log events..
  40. Mon Jun 10 11:25:59 2019 - [info] New master is db2(10.100.64.120:3306)
  41. Mon Jun 10 11:25:59 2019 - [info] Starting master failover..
  42. Mon Jun 10 11:25:59 2019 - [info] 
  43. From:
  44. db1(10.100.64.119:3306) (current master)
  45.  +--db2(10.100.64.120:3306)
  46.  +--db3(10.100.64.121:3306)
  48. To:
  49. db2(10.100.64.120:3306) (new master)
  50.  +--db3(10.100.64.121:3306)
  51. Mon Jun 10 11:25:59 2019 - [info] 
  52. Mon Jun 10 11:25:59 2019 - [info] * Phase 3.3: New Master Recovery Phase..
  53. Mon Jun 10 11:25:59 2019 - [info] 
  54. Mon Jun 10 11:25:59 2019 - [info]  Waiting all logs to be applied.. 
  55. Mon Jun 10 11:25:59 2019 - [info]   done.
  56. Mon Jun 10 11:25:59 2019 - [info] Getting new master's binlog name and position..
  57. Mon Jun 10 11:25:59 2019 - [info]  mysql-bin.000032:194
  58. Mon Jun 10 11:25:59 2019 - [info]  All other slaves should start replication from here. Statement should be: CHANGE MASTER TO MASTER_HOST='db2 or 10.100.64.120', MASTER_PORT=3306, MASTER_AUTO_POSITION=1, MASTER_USER='repl', MASTER_PASSWORD='xxx';
  59. Mon Jun 10 11:25:59 2019 - [info] Master Recovery succeeded. File:Pos:Exec_Gtid_Set: mysql-bin.000032, 194, 479dbc89-e31e-11e8-83eb-005056a8803c:1-696587
  60. Mon Jun 10 11:25:59 2019 - [info] Executing master IP activate script:
  61. Mon Jun 10 11:25:59 2019 - [info]   /etc/masterha/master_ip_failover --command=start --ssh_user=root --orig_master_host=db1 --orig_master_ip=10.100.64.119 --orig_master_port=3306 --new_master_host=db2 --new_master_ip=10.100.64.120 --new_master_port=3306 --new_master_user='xucl'  --orig_master_ssh_port=52000  --new_master_ssh_port=52000 --new_master_password=xxx
  62. Set read_only=0 on the new master.
  63. add vip to new master
  64. Warning: Permanently added '[db2]:52000' (ECDSA) to the list of known hosts.
  65. Mon Jun 10 11:25:59 2019 - [info]  OK.
  66. Mon Jun 10 11:25:59 2019 - [info] ** Finished master recovery successfully.
  67. Mon Jun 10 11:25:59 2019 - [info] * Phase 3: Master Recovery Phase completed.

整个第三阶段步骤是最多的，主要有如下：

  • 3.1: Getting Latest Slaves Phase
  • 该阶段主要通过复制信息确定哪个slave节点有最新的binlog
  • 3.2: Saving Dead Master’s Binlog Phase
  • 保存dead master上的binlog，如果是由于down机导致无法ssh，那么会提示Transactions that were not sent to the latest slave (Read_Master_Log_Pos to the tail of the dead master's binlog) were lost
  • 3.3: Determining New Master Phase
  • 该阶段即确认哪个slave节点会被选为新的master节点
  • 3.4：New Master Diff Log Generation Phase
  • 该阶段即调用save_binary_logs来补齐binlog
  • 3.5: Master Log Apply Phase
  • 等待新master应用完全部的binlog，确定应用完日志的最新位点，生成change master to语句
  • 完成以后调用failover命令
  1. /etc/masterha/master_ip_failover --command=start --ssh_user=root --orig_master_host=db1 --orig_master_ip=10.100.64.119 --orig_master_port=3306 --new_master_host=db2 --new_master_ip=10.100.64.120 --new_master_port=3306 --new_master_user='xucl'  --orig_master_ssh_port=52000  --new_master_ssh_port=52000 --new_master_password=xxx

这里调用start命令，源码如下：

  1. elsif ( $command eq "start" ) {
  3.     # all arguments are passed.
  4.     # If you manage master ip address at global catalog database,
  5.     # activate new_master_ip here.
  6.     # You can also grant write access (create user, set read_only=0, etc) here.
  7.     my $exit_code = 10;
  8.     eval {
  9.       my $new_master_handler = new MHA::DBHelper();
  11.       # args: hostname, port, user, password, raise_error_or_not
  12.       $new_master_handler->connect( $new_master_ip, $new_master_port,
  13.         $new_master_user, $new_master_password, 1 );
  15.       ## Set read_only=0 on the new master
  16.       $new_master_handler->disable_log_bin_local();
  17.       print "Set read_only=0 on the new master.\n";
  18.       $new_master_handler->disable_read_only();
  20.       ## Creating an app user on the new master
  21.       #print "Creating app user on the new master..\n";
  22.       #FIXME_xxx_create_user( $new_master_handler->{dbh} );
  23.       $new_master_handler->enable_log_bin_local();
  24.       $new_master_handler->disconnect();
  26.       ## Update master ip on the catalog database, etc
  27.       &add_vip();
  28.       $exit_code = 0;
  29.     };
  30.     if ($@) {
  31.       warn $@;
  33.       # If you want to continue failover, exit 10.
  34.       exit $exit_code;
  35.     }
  36.     exit $exit_code;
  37.   }

这里实际上执行的是设置read_only，然后绑定VIP的操作

Phase 4: Slaves Recovery Phase

  • Phase 4.1: Starting Parallel Slave Diff Log Generation Phase
  • 其他从库全部应用完relay log以后，从新的master上补齐差异binlog
  • Phase 4.2: Starting Parallel Slave Log Apply Phase
  • 其他节点应用差异的binlog

Phase 5: New master cleanup phase

该阶段即清理new master上的slave信息

最后完成fail over后，给出简单的报告：

  1. app1: MySQL Master failover db1(10.100.64.119:3306) to db2(10.100.64.120:3306) succeeded
  3. Master db1(10.100.64.119:3306) is down!
  5. Check MHA Manager logs at manager:/var/log/masterha/app1/app1.log for details.
  7. Started automated(non-interactive) failover.
  8. Invalidated master IP address on db1(10.100.64.119:3306)
  9. Selected db2(10.100.64.120:3306) as a new master.
  10. db2(10.100.64.120:3306): OK: Applying all logs succeeded.
  11. db2(10.100.64.120:3306): OK: Activated master IP address.
  12. db3(10.100.64.121:3306): OK: Slave started, replicating from db2(10.100.64.120:3306)
  13. db2(10.100.64.120:3306): Resetting slave info succeeded.
  14. Master failover to db2(10.100.64.120:3306) completed successfully.

简单给出了从哪个节点选举了新的master节点，其他节点成功复制，failover完成

【MySQL】从General Log看MHA原理 - 图1