KingbaseES V8R3集群运维案例之---主库系统down failover切换过程分析

​案例说明：
KingbaseES V8R3集群failover时两个cluster都会触发，但只有一个cluster会调用脚本去执行真正的切换流程，另一个有对应的打印，但不会调用脚本，只是走相关的流程去修改状态。 那么你需要确认一点，到底是主库还是备库的cluster在执行脚本，关键字：failover_stream.sh ，看cluster.log中有没有这个的名称。本案例通过主库系统宕机，分析了failover 切换过程。

适用版本： KingbaseES V8R3

集群节点状态信息：

# 集群节点状态信息
TEST=# show pool_nodes;
 node_id |   hostname    | port  | status | lb_weight |  role   | select_cnt | load_balance_node | replication_delay
---------+---------------+-------+--------+-----------+---------+------------+-------------------+-------------------
 0       | 192.168.1.101 | 54321 | up     | 0.500000  | primary | 1          | true              | 0
 1       | 192.168.1.102 | 54321 | up     | 0.500000  | standby | 0          | false             | 0
(2 rows)

对于KingbaseES V8R3集群failover切换的分析：

1. 可以通过主备库的cluster.log，获取整个主备切换的过程。
2. 从failover.log日志中获取执行failover过程，注意只有执行failover_stream.sh的节点才会产生failover.log。
3. recovery.log日志记录了原主库failover完成后，从主库recovery为新备库的过程。

一、Failover切换过程分析

关闭主库系统：[root@node101 ~]# shutdown -h now

备库cluster.log日志分析：(主库系统关机，备库调用failover_stream.sh执行failover切换)

1、主备库处于正常状态时，备库收到主库的heartbeat。

2022-08-30 15:38:03: pid 17612: DETAIL:  the last heartbeat from "192.168.1.101:9999" received 0 seconds ago
2022-08-30 15:38:06: pid 17612: LOG:  watchdog checking if kingbasecluster is alive using heartbeat
2022-08-30 15:38:06: pid 17612: DETAIL:  the last heartbeat from "192.168.1.101:9999" received 0 seconds ago

2、备库kingbasecluster检测到主库集群服务和数据库服务shutdown，kingbasecluster发生主备切换，当前的kingbasecluster由standby切换为master。

2022-08-30 15:38:09: pid 17585: LOG:  remote node "192.168.1.101:9999 Linux node101" is shutting down
2022-08-30 15:38:09: pid 17585: LOG:  watchdog cluster has lost the coordinator node
2022-08-30 15:38:09: pid 17585: LOG:  unassigning the remote node "192.168.1.101:9999 Linux node101" from watchdog cluster master
2022-08-30 15:38:09: pid 17585: LOG:  We have lost the cluster master node "192.168.1.101:9999 Linux node101"
2022-08-30 15:38:09: pid 17585: LOG:  watchdog node state changed from [STANDBY] to [JOINING]
2022-08-30 15:38:09: pid 17612: LOG:  watchdog checking if kingbasecluster is alive using heartbeat
2022-08-30 15:38:09: pid 17612: DETAIL:  the last heartbeat from "192.168.1.101:9999" received 1 seconds ago
2022-08-30 15:38:10: pid 17547: ERROR:  failed to authenticate
2022-08-30 15:38:10: pid 17547: DETAIL:  the database system is shutting down
2022-08-30 15:38:12: pid 17612: LOG:  watchdog checking if kingbasecluster is alive using heartbeat
2022-08-30 15:38:12: pid 17612: DETAIL:  the last heartbeat from "192.168.1.101:9999" received 4 seconds ago

3、备库kingbasecluster对主库的数据库服务根据：health_check_max_retries * health_check_retry_delay配置尝试连接。

2022-08-30 15:38:13: pid 17547: LOG:  health checking retry count 1
2022-08-30 15:38:13: pid 17585: LOG:  watchdog node state changed from [JOINING] to [INITIALIZING]
2022-08-30 15:38:14: pid 17585: LOG:  I am the only alive node in the watchdog cluster
2022-08-30 15:38:14: pid 17585: HINT:  skipping stand for coordinator state
2022-08-30 15:38:14: pid 17585: LOG:  watchdog node state changed from [INITIALIZING] to [MASTER]
2022-08-30 15:38:14: pid 17585: LOG:  I am announcing my self as master/coordinator watchdog node
2022-08-30 15:38:15: pid 17612: LOG:  watchdog checking if kingbasecluster is alive using heartbeat
2022-08-30 15:38:15: pid 17612: DETAIL:  the last heartbeat from "192.168.1.101:9999" received 7 seconds ago
2022-08-30 15:38:18: pid 17585: LOG:  I am the cluster leader node
2022-08-30 15:38:18: pid 17585: DETAIL:  our declare coordinator message is accepted by all nodes
2022-08-30 15:38:18: pid 17585: LOG:  setting the local node "192.168.1.102:9999 Linux node102" as watchdog cluster master

4、备库开启升级进程(escalation process)，cluster vip漂移到新的master节点。

2022-08-30 15:38:18: pid 17585: LOG:  I am the cluster leader node. Starting escalation process
2022-08-30 15:38:18: pid 17585: LOG:  escalation process started with PID:22088
2022-08-30 15:38:18: pid 17547: LOG:  connect_inet_domain_socket: select() interrupted by certain signal. retrying...
2022-08-30 15:38:18: pid 22088: LOG:  watchdog: escalation started
2022-08-30 15:38:18: pid 17612: LOG:  watchdog checking if kingbasecluster is alive using heartbeat
2022-08-30 15:38:18: pid 17612: DETAIL:  the last heartbeat from "192.168.1.101:9999" received 10 seconds ago
2022-08-30 15:38:21: pid 22088: LOG:  successfully acquired the delegate IP:"192.168.1.201"
2022-08-30 15:38:21: pid 22088: DETAIL:  'if_up_cmd' returned with success
.......

5、 备库对原主库数据库服务的连接次数超过阈值后，将原主库的数据库服务设置为down状态。

2022-08-30 15:39:20: pid 17547: LOG:  health checking retry count 10
2022-08-30 15:39:22: pid 17612: LOG:  watchdog checking if kingbasecluster is alive using heartbeat
2022-08-30 15:39:22: pid 17612: DETAIL:  the last heartbeat from "192.168.1.101:9999" received 73 seconds ago
2022-08-30 15:39:23: pid 17547: LOG:  failed to connect to kingbase server on "192.168.1.101:54321", getsockopt() detected error "
No route to host"
2022-08-30 15:39:23: pid 17547: ERROR:  failed to make persistent db connection
2022-08-30 15:39:23: pid 17547: DETAIL:  connection to host:"192.168.1.101:54321" failed
2022-08-30 15:39:23: pid 17547: LOG:  setting backend node 0 status to NODE DOWN

6、 收到本节点kingbasecluster发出的failover request，并获取到failover lock。

2022-08-30 15:39:23: pid 17547: LOG:  received degenerate backend request for node_id: 0 from pid [17547]
2022-08-30 15:39:23: pid 17585: LOG:  new IPC connection received
2022-08-30 15:39:23: pid 17585: LOG:  watchdog received the failover command from local kingbasecluster on IPC interface
2022-08-30 15:39:23: pid 17585: LOG:  watchdog is processing the failover command [DEGENERATE_BACKEND_REQUEST] received from local
 kingbasecluster on IPC interface
2022-08-30 15:39:23: pid 17585: LOG:  I am the only kingbasecluster node in the watchdog cluster
2022-08-30 15:39:23: pid 17585: DETAIL:  no need to propagate the failover command [DEGENERATE_BACKEND_REQUEST]
2022-08-30 15:39:23: pid 17585: LOG:  new IPC connection received
2022-08-30 15:39:23: pid 17585: LOG:  received the failover command lock request from local kingbasecluster on IPC interface
2022-08-30 15:39:23: pid 17585: LOG:  local kingbasecluster node "192.168.1.102:9999 Linux node102" is requesting to become a lock
 holder for failover ID: 0

7、 获取到failover lock后，开始执行failover_stream.sh进行failover的切换。

2022-08-30 15:39:23: pid 17585: LOG:  local kingbasecluster node "192.168.1.102:9999 Linux node102" is the lock holder
2022-08-30 15:39:23: pid 17547: LOG:  starting degeneration. shutdown host 192.168.1.101(54321)
2022-08-30 15:39:23: pid 17547: LOG:  Restart all children
2022-08-30 15:39:23: pid 17547: LOG:  execute command: /home/kingbase/cluster/R3HA/kingbasecluster/bin/failover_stream.sh 192.168.
1.102 0 0 192.168.1.101 192.168.1.101 1 0 /home/kingbase/cluster/R3HA/db/data
2022-08-30 15:39:25: pid 17612: LOG:  watchdog checking if kingbasecluster is alive using heartbeat
2022-08-30 15:39:25: pid 17612: DETAIL:  the last heartbeat from "192.168.1.101:9999" received 76 seconds ago
ssh: connect to host 192.168.1.101 port 22: No route to host
2022-08-30 15:39:31: pid 17612: LOG:  watchdog checking if kingbasecluster is alive using heartbeat
2022-08-30 15:39:31: pid 17612: DETAIL:  the last heartbeat from "192.168.1.101:9999" received 82 seconds ago
2022-08-30 15:39:33: pid 17585: LOG:  new IPC connection received
2022-08-30 15:39:33: pid 17585: LOG:  received the failover command lock request from local kingbasecluster on IPC interface
2022-08-30 15:39:33: pid 17585: LOG:  local kingbasecluster node "192.168.1.102:9999 Linux node102" is requesting to release [FAIL
OVER] lock for failover ID 0

8、执行failover切换，并查找新的primary。(当前备库切换为primary)

2022-08-30 15:39:33: pid 17547: LOG:  find_primary_node_repeatedly: waiting for finding a primary node
2022-08-30 15:39:33: pid 17547: LOG:  find_primary_node: checking backend no 0
2022-08-30 15:39:33: pid 17547: LOG:  find_primary_node: checking backend no 1
2022-08-30 15:39:33: pid 17547: LOG:  find_primary_node: primary node id is 1
2022-08-30 15:39:33: pid 17585: LOG:  new IPC connection received
2022-08-30 15:39:33: pid 17585: LOG:  received the failover command lock request from local kingbasecluster on IPC interface
2022-08-30 15:39:33: pid 17585: LOG:  local kingbasecluster node "192.168.1.102:9999 Linux node102" is requesting to release [FOLL
OW MASTER] lock for failover ID 0
2022-08-30 15:39:33: pid 17585: LOG:  local kingbasecluster node "192.168.1.102:9999 Linux node102" has released the [FOLLOW MASTE
R] lock for failover ID 0
2022-08-30 15:39:33: pid 17547: LOG:  failover: set new primary node: 1
2022-08-30 15:39:33: pid 17547: LOG:  failover: set new master node: 1
2022-08-30 15:39:33: pid 21501: LOG:  worker process received restart request
2022-08-30 15:39:33: pid 17585: LOG:  new IPC connection received
2022-08-30 15:39:33: pid 17585: LOG:  received the failover command lock request from local kingbasecluster on IPC interface
2022-08-30 15:39:33: pid 17585: LOG:  local kingbasecluster node "192.168.1.102:9999 Linux node102" is requesting to resign from a
 lock holder for failover ID 0
2022-08-30 15:39:33: pid 17585: LOG:  local kingbasecluster node "192.168.1.102:9999 Linux node102" has resigned from the lock hol
der
failover done. shutdown host 192.168.1.101(54321)2022-08-30 15:39:33: pid 17547: LOG:  failover done. shutdown host 192.168.1.101(
54321)

备库Failover.log分析：

1、执行failover_stream.sh进行failover切换

-----------------2022-08-30 15:39:23 failover beging---------------------------------------
----failover-stats is %H = hostname of the new master node [192.168.1.102], %P = old primary node id [0], %d = node id[0], %h = host name [192.168.1.101], %O = old primary host[192.168.1.101] %m = new master node id [1], %M = old master node id [0], %D = database cluster path [/home/kingbase/cluster/R3HA/db/data].

Tips：
     1)new_master : 192.168.1.102
     2) new_master_id:   1
     3) old_primary: 192.168.1.101
     4) old_primary_id : 0

2、ping 网关测试网络连通性

----ping trust ip
ping trust ip 192.168.1.1 success

3、ssh连接远程原主库，执行关闭数据库服务和释放db vip；并将db vip加载到当前主库节点。

----determine whether the faulty db is master or standby
master down, let 192.168.1.102 become new primary.....
 2022-08-30 15:39:25 del old primary VIP on 192.168.1.101
ssh connect host:192.168.1.101 failed, can not stop old primary db and del old primary db vip
2022-08-30 15:39:29 add VIP on 192.168.1.102
ADD VIP NOW AT 2022-08-30 15:39:30 ON enp0s3
execute: [/sbin/ip addr add 192.168.1.200/24 dev enp0s3 label enp0s3:2]
execute: /home/kingbase/cluster/R3HA/db/bin/arping -U 192.168.1.200 -I enp0s3 -w 1
ARPING 192.168.1.200 from 192.168.1.200 enp0s3
Sent 1 probes (1 broadcast(s))
Received 0 response(s)
2022-08-30 15:39:31 promote begin...let 192.168.1.102 become master

4、通过连接db vip执行“select 33333”测试当前数据库服务状态，如果正常，执行promote，提升为新主库，将同步模式设为async。

check db if is alive
ksql "port=54321 user=SUPERMANAGER_V8ADMIN  dbname=TEST connect_timeout=10"  -c "select 33333;"
2022-08-30 15:39:31 kingbase is ok , to prepare execute promote
execute promote
server promoting
check db if is alive after promote
ksql "port=54321 user=SUPERMANAGER_V8ADMIN  dbname=TEST connect_timeout=10"  -c "select 33333;"
2022-08-30 15:39:32 after execute promote , kingbase status is ok.
after execute promote, kingbase is ok.
2022-08-30 15:39:32 sync to async
ALTER SYSTEM
 SYS_RELOAD_CONF
-----------------
 t
(1 row)

5、连接新主库数据库服务，如果成功，在新主库上执行checkpoint，checkpoint成功，则failover切换完成。

2022-08-30 15:39:32 make checkpoint
check the db to see if it is alive
ksql "port=54321 user=SUPERMANAGER_V8ADMIN dbname=TEST connect_timeout=10"  -c "select 33333;"
2022-08-30 15:39:32 kingbase is ok , to prepare execute checkpoint
execute checkpoint
CHECKPOINT
check the db to see if it is alive after execute checkpoint
ksql "port=54321 user=SUPERMANAGER_V8ADMIN  dbname=TEST connect_timeout=10"  -c "select 33333;"
2022-08-30 15:39:33 after execute checkpoint, kingbase is ok.
after execute checkpoint, kingbase is ok.
-----------------2022-08-30 15:39:33 failover end---------------------------------------

二、原主库recovery为新备库

1、在原主库生成recovery.conf文件(系统通过crond计划任务，调用network_rewind.sh脚本自动recovery为备库)[kingbase@node101 data]$ cp ../etc/recovery.done ./recovery.conf

2、查看recovery.log日志信息

[kingbase@node101 log]$  more recovery.log
---------------------------------------------------------------------

1)开启recovery，检测存储读写功能是否正常。

2022-08-30 16:42:01 recover beging...
my pid is 11927,officially began to perform recovery
2022-08-30 16:42:01 check read/write on mount point
2022-08-30 16:42:01 check read/write on mount point (1 / 6).
2022-08-30 16:42:01 stat the directory of the mount point "/home/kingbase/cluster/R3HA/db/data" ...
2022-08-30 16:42:01 stat the directory of the mount point "/home/kingbase/cluster/R3HA/db/data" ... OK
2022-08-30 16:42:01 create/write the file "/home/kingbase/cluster/R3HA/db/data/rw_status_file_574940445" ...
2022-08-30 16:42:01 create/write the file "/home/kingbase/cluster/R3HA/db/data/rw_status_file_574940445" ... OK
2022-08-30 16:42:01 stat the file "/home/kingbase/cluster/R3HA/db/data/rw_status_file_574940445" ...
2022-08-30 16:42:01 stat the file "/home/kingbase/cluster/R3HA/db/data/rw_status_file_574940445" ... OK
2022-08-30 16:42:01 read the file "/home/kingbase/cluster/R3HA/db/data/rw_status_file_574940445" ...
2022-08-30 16:42:01 read the file "/home/kingbase/cluster/R3HA/db/data/rw_status_file_574940445" ... OK
2022-08-30 16:42:01 delete the file "/home/kingbase/cluster/R3HA/db/data/rw_status_file_574940445" ...
2022-08-30 16:42:01 delete the file "/home/kingbase/cluster/R3HA/db/data/rw_status_file_574940445" ... OK
2022-08-30 16:42:01 success to check read/write on mount point (1 / 6).
2022-08-30 16:42:01 check read/write on mount point ... ok

2)ping 网关检测网络的连通性

2022-08-30 16:42:01 check if the network is ok
ping trust ip 192.168.1.1 success ping times :[3], success times:[2]

3)判断当前节点role(master OR standby),如果是standby节点，并判断是否需要recovery。( I,m status is [1] (1 is down), I will be in recovery.)

determine if i am master or standby
 node_id |   hostname    | port  | status | lb_weight |  role   | select_cnt | load_balance_node | replication_delay
---------+---------------+-------+--------+-----------+---------+------------+-------------------+-------------------
 0       | 192.168.1.101 | 54321 | down   | 0.500000  | standby | 0          | false             | 0
 1       | 192.168.1.102 | 54321 | up     | 0.500000  | primary | 0          | true              | 0
(2 rows)

i am standby in cluster,determine if recovery is needed
2022-08-30 16:42:03 now will del vip [192.168.1.200/24]
but no 192.168.1.200/24 on my DEV, nothing to do with del
ksql execute success,but node:node101 does not have correct streaming(or catchup) replication ,will retry ,retry times:[1/10]
......
ksql execute success,but node:node101 does not have correct streaming(or catchup) replication ,will retry ,retry times:[10/10]
primary node/Im node status is changed, primary ip[192.168.1.102], recovery.conf NEED_CHANGE [0] (0 is need ), I,m status is [1] (1 is down), I will be in recovery.
 node_id |   hostname    | port  | status | lb_weight |  role   | select_cnt | load_balance_node | replication_delay
---------+---------------+-------+--------+-----------+---------+------------+-------------------+-------------------
 0       | 192.168.1.101 | 54321 | down   | 0.500000  | standby | 0          | false             | 0
 1       | 192.168.1.102 | 54321 | up     | 0.500000  | primary | 0          | true              | 0
(2 rows)

4)如果需要做recovery，执行sys_rewind。

if recover node up, let it down , for rewind
2022-08-30 16:42:34 sys_rewind...
sys_rewind  --target-data=/home/kingbase/cluster/R3HA/db/data --source-server="host=192.168.1.102 port=54321 user=SUPERMANAGER_V8ADMIN dbname=TEST"
datadir_source = /home/kingbase/cluster/R3HA/db/data
rewinding from last common checkpoint at 0/66000028 on timeline 15
find last common checkpoint start time from 2022-08-30 16:42:34.727711 CST to 2022-08-30 16:42:34.839545 CST, in "0.111834" seconds.
reading source file list
reading target file list
reading WAL in target
Rewind datadir file from source
update the control file: minRecoveryPoint is '0/68024E80', minRecoveryPointTLI is '16', and database state is 'in archive recovery'
rewind start wal location 0/66000028 (file 0000000F0000000000000066), end wal location 0/68024E80 (file 000000100000000000000068). time from 2022-08-30 16:42:36.727711 CST to 2022-08-30 16:42:37.201678 CST, in "2.473967" seconds.
Done!

5)sys_rewind成功，修改集群配置文件。

sed conf change #synchronous_standby_names
2022-08-30 16:42:39 file operate
cp recovery.conf...
 change recovery.conf ip -> primary.ip
2022-08-30 16:42:39 no need change recovery.conf, primary node is 192.168.1.102

6)启动新备库数据库服务，删除原复制槽并重建。备库数据库服务启动成功后，配置同步为sync。

delete pid file if exist
del the replication_slots if exis
drop the slot [slot_node101].
drop the slot [slot_node102].
2022-08-30 16:42:39 start up the kingbase...
waiting for server to start....LOG:  redirecting log output to logging collector process
HINT:  Future log output will appear in directory "/home/kingbase/cluster/R3HA/db/data/sys_log".
 done
server started
ksql "port=54321 user=SUPERMANAGER_V8ADMIN dbname=TEST connect_timeout=10"   -c "select 33333;"
 SYS_CREATE_PHYSICAL_REPLICATION_SLOT
--------------------------------------
 (slot_node101,)
(1 row)

2022-08-30 16:42:41 create the slot [slot_node101] success.
 SYS_CREATE_PHYSICAL_REPLICATION_SLOT
--------------------------------------
 (slot_node102,)
(1 row)

2022-08-30 16:42:41 create the slot [slot_node102] success.
2022-08-30 16:42:41 start up standby successful!
cluster is sync cluster.
SYNC RECOVER MODE ...
2022-08-30 16:42:41 remote primary node change sync
ALTER SYSTEM
 SYS_RELOAD_CONF
-----------------
 t
(1 row)

SYNC RECOVER MODE DONE

7)执行pcp_attach_node将当前节点加入到集群。

2022-08-30 16:42:44 attach pool...
IM Node is 0, will try [pcp_attach_node -U kingbase -W MTIzNDU2 -h 192.168.1.201 -n 0]
pcp_attach_node -- Command Successful
 node_id |   hostname    | port  | status | lb_weight |  role   | select_cnt | load_balance_node | replication_delay
---------+---------------+-------+--------+-----------+---------+------------+-------------------+-------------------
 0       | 192.168.1.101 | 54321 | up     | 0.500000  | standby | 0          | false             | 0
 1       | 192.168.1.102 | 54321 | up     | 0.500000  | primary | 0          | true              | 0
(2 rows)

2022-08-30 16:42:45 attach end..
recovery success,exit script with success

三、总结
通过对原主库执行系统重启服务，如果备库在阈值范围内尝试连接主库数据库服务失败，其failover切换过程和主库系统shutdown是一致的。