PostgreSQL源码系列三：PGPool-II BUG? down节点在线恢复问题

一. 前言

在PostGreSQL的高可用部署中，Patroni&PGPool-II是比较常用的方案，前者系统架构&配置均相对复杂，但性能比较优异；后者整体架构相对简单，但性能方面存在些许问题，故障恢复方面它使用pg_basebackup，相对pg_rewind，效率天差地别！
配置方面不再赘述，网上资料比较多。

二. 问题

目前，有套测试环境采用了PGPool-II部署，主库故障后，在恢复阶段报了如下错误：

2.1 在线恢复错误

pgpool@k8s02 ~]$ psql -hk8s02 -p 9999 -U postgres -c "show pool_nodes"
 node_id | hostname | port | status | lb_weight |  role   | select_cnt | load_balance_node | replication_delay | replication_state | replication_sync_state | last_status_change  
---------+----------+------+--------+-----------+---------+------------+-------------------+-------------------+-------------------+------------------------+---------------------
 0       | k8s01    | 5432 | down   | 0.500000  | standby | 0          | false             | 0                 |                   |                        | 2021-11-09 16:59:24
 1       | k8s02    | 5432 | up     | 0.500000  | primary | 2          | true              | 0                 |                   |                        | 2021-11-09 16:59:25
(2 rows)

pgpool@k8s02 ~]$ pcp_recovery_node -h k8s01 -p 9898 -U pgpool -n 0
Password:
ERROR: executing recovery, execution of command failed at “1st stage”
DETAIL: command:"/u01/app/pgpool4.2.5/etc/recovery_1st_stage"

2.2 replication slot "“k8s01"” does not exist
第一个错误解决以后，故障节点恢复，PostGreSQL启动，但pg日志有报如下错误，导致数据无法同步：

2021-11-10 17:03:52.808 CST,,,2788,,618bb528.ae4,1,,2021-11-10 17:03:52 CST,,0,FATAL,XX000,"could not start WAL streaming: ERROR:  replication slot ""k8s01"" does not exist",,,,,,,,,"","walreceiver"
2021-11-10 17:03:57.816 CST,"postgres","",2795,"192.168.100.101:39314",618bb52d.aeb,1,"idle",2021-11-10 17:03:57 CST,2/0,0,ERROR,42704,"replication slot ""k8s01"" does not exist",,,,,,"START_REPLICATION SLOT ""k8s01"" 0/7000000 TIMELINE 2",,,"walreceiver","walsender"
2021-11-10 17:03:57.816 CST,,,2794,,618bb52d.aea,1,,2021-11-10 17:03:57 CST,,0,FATAL,XX000,"could not start WAL streaming: ERROR:  replication slot ""k8s01"" does not exist",,,,,,,,,"","walreceiver"

三. 处理过程

3.1 解决在线恢复错误
既然报错涉及bash脚本，那我们单独运行下recovery_1st_stage
[postgres@k8s02 etc]$./recovery_1st_stage ‘/data/pg13.4’ ‘k8s01’ ‘/data/pg13.4’ 5432 0 5432
…
…
+echo recovery_1st_stage: end: recovery_1st_stage is completed successfully
recovery_1st_stage: end: recovery_1st_stage is completed successfully
+exit 0
发现居然是成功的，那么很可能是pcp_recovery_node在调用此脚本时出了问题，我们看下源码，简单搜索报错关键字，发现在如下function中

/*
 * Call pgpool_recovery() function.
 */
static void
exec_recovery(PGconn *conn, BackendInfo * main_backend, BackendInfo * recovery_backend, char stage, int recovery_node)
{
	PGresult   *result;
	char	   *hostname;
	char	   *script;

	if (strlen(recovery_backend->backend_hostname) == 0 || *(recovery_backend->backend_hostname) == '/')
		hostname = "localhost";
	else
		hostname = recovery_backend->backend_hostname;

	script = (stage == FIRST_STAGE) ?
		pool_config->recovery_1st_stage_command : pool_config->recovery_2nd_stage_command;

	if (script == NULL || strlen(script) == 0)
	{
		/* do not execute script */
		return;
	}

	/*
	 * Execute recovery command
	 */
	snprintf(recovery_command,
			 sizeof(recovery_command),
			 "SELECT pgpool_recovery('%s', '%s', '%s', '%d', %d, '%d')",
			 script,
			 hostname,
			 recovery_backend->backend_data_directory,
			 main_backend->backend_port,
			 recovery_node,
			 recovery_backend->backend_port
		);

	ereport(LOG,
			(errmsg("executing recovery"),
			 errdetail("starting recovery command: \"%s\"", recovery_command)));

	ereport(LOG,
			(errmsg("executing recovery"),
			 errdetail("disabling statement_timeout")));

	result = PQexec(conn, "SET statement_timeout To 0");
	if (PQresultStatus(result) != PGRES_COMMAND_OK)
		ereport(ERROR,
				(errmsg("executing recovery, SET STATEMENT_TIMEOUT failed at \"%s\"",
						(stage == FIRST_STAGE) ? "1st stage" : "2nd stage")));

	PQclear(result);

	ereport(DEBUG1,
			(errmsg("executing recovery, start recovery")));

	result = PQexec(conn, recovery_command);
	if (PQresultStatus(result) != PGRES_TUPLES_OK)
		ereport(ERROR,
				(errmsg("executing recovery, execution of command failed at \"%s\"",
						(stage == FIRST_STAGE) ? "1st stage" : "2nd stage"),
				 errdetail("command:\"%s\"", script)));

	PQclear(result);

	ereport(DEBUG1,
			(errmsg("executing recovery, finish recovery")));
}

在此function中发现SQL:SELECT pgpool_recovery(’%s’, ‘%s’, ‘%s’, ‘%d’, %d, ‘%d’)，此function就是我们安装PGPool&配置在线恢复时产生的，位于template1下：

CREATE OR REPLACE FUNCTION public.pgpool_recovery(script_name text, remote_host text, remote_data_directory text, primary_port text, remote_node integer, remote_port text)
 RETURNS boolean
 LANGUAGE c
 STRICT
AS '$libdir/pgpool-recovery', $function$pgpool_recovery$function$
;

它实际上调用了C语言的function:pgpool_recovery,我们看下它的C代码：

Datum
pgpool_recovery(PG_FUNCTION_ARGS)
{
	int			r;
	char	   *script = DatumGetCString(DirectFunctionCall1(textout,
															 PointerGetDatum(PG_GETARG_TEXT_P(0))));

	char	   *remote_host = DatumGetCString(DirectFunctionCall1(textout,
																  PointerGetDatum(PG_GETARG_TEXT_P(1))));
	char	   *remote_data_directory = DatumGetCString(DirectFunctionCall1(textout,
																			PointerGetDatum(PG_GETARG_TEXT_P(2))));

	if (!superuser())
#ifdef ERRCODE_INSUFFICIENT_PRIVILEGE
		ereport(ERROR,
				(errcode(ERRCODE_INSUFFICIENT_PRIVILEGE),
				 (errmsg("must be superuser to use pgpool_recovery function"))));
#else
		elog(ERROR, "must be superuser to use pgpool_recovery function");
#endif

	if (PG_NARGS() >= 6)		/* Pgpool-II 4.1 or later */
	{
		char	   *primary_port = DatumGetCString(DirectFunctionCall1(textout,
																	  PointerGetDatum(PG_GETARG_TEXT_P(3))));
		int			remote_node = PG_GETARG_INT32(4);

		char	   *remote_port = DatumGetCString(DirectFunctionCall1(textout,
																	  PointerGetDatum(PG_GETARG_TEXT_P(5))));

		snprintf(recovery_script, sizeof(recovery_script), "\"%s/%s\" \"%s\" \"%s\" \"%s\" \"%s\" %d \"%s\"",
				 DataDir, script, DataDir, remote_host,
				 remote_data_directory, primary_port, remote_node, remote_port);
	}
	else if (PG_NARGS() >= 5)		/* Pgpool-II 4.0 */
	{
		char	   *primary_port = DatumGetCString(DirectFunctionCall1(textout,
																	  PointerGetDatum(PG_GETARG_TEXT_P(3))));
		int			remote_node = PG_GETARG_INT32(4);

		snprintf(recovery_script, sizeof(recovery_script), "\"%s/%s\" \"%s\" \"%s\" \"%s\" \"%s\" %d",
				 DataDir, script, DataDir, remote_host,
				 remote_data_directory, primary_port, remote_node);
	}
	else if (PG_NARGS() >= 4)	/* Pgpool-II 3.4 - 3.7 */
	{
		char	   *primary_port = DatumGetCString(DirectFunctionCall1(textout,
																	  PointerGetDatum(PG_GETARG_TEXT_P(3))));

		snprintf(recovery_script, sizeof(recovery_script), "\"%s/%s\" \"%s\" \"%s\" \"%s\" \"%s\"",
				 DataDir, script, DataDir, remote_host,
				 remote_data_directory, primary_port);
	}
	else
	{
		snprintf(recovery_script, sizeof(recovery_script), "\"%s/%s\" \"%s\" \"%s\" \"%s\"",
				 DataDir, script, DataDir, remote_host,
				 remote_data_directory);
	}

	elog(DEBUG1, "recovery_script: %s", recovery_script);
	r = system(recovery_script);

	if (r != 0)
	{
		elog(ERROR, "pgpool_recovery failed");
	}

	PG_RETURN_BOOL(true);
}

system(recovery_script)实际上就是执行了recovery_1st_stage，至于具体内容，需要打印出来看下，正好上面有做了DEBUG1级别的日志，只要开启即可，但是DEBUG1具体是什么意思？看elog.h中的代码：

#define DEBUG1		14			/* used by GUC debug_* variables */

这个GUC就是Grand Unified Configuration，指的是postgreSQL通过对数据库变量进行设置对数据库进行控制的机制。简单讲就是postgresql.conf中的变量，那就好办了，我们调整下：

重启PG，看到如下日志：
more postgresql-Wed.csv

2021-11-10 16:28:20.355 CST,,,1664,,618b82a4.680,1,,2021-11-10 16:28:20 CST,3/0,0,DEBUG,00000,"autovacuum: processing database ""postgres""",,,,,,,,,"","autovacuum worker"
2021-11-10 16:28:35.429 CST,"postgres","template1",1670,"192.168.100.101:38248",618b82b3.686,1,
"SELECT",2021-11-10 16:28:35 CST,3/158,0,DEBUG,00000,"recovery_script: ""/data/pg13.4//u01/app/pgpool4.2.5/etc/recovery_1st_stage"" ""/data/pg13.4"" ""k8s01"" ""/data/pg13.4"" ""5432"" 0 ""5432""",,,,,,"SELECT pgpool_recovery('/u01/app/pgpool4.2.5/etc/recovery_1st_stage', 'k8s01', '/data/pg13.4', '5432', 0, '5432')",,,"","client backend"
2021-11-10 16:28:35.431 CST,"postgres","template1",1670,"192.168.100.101:38248",618b82b3.686,2,
"SELECT",2021-11-10 16:28:35 CST,3/158,0,ERROR,XX000,"pgpool_recovery failed",,,,,,"SELECT pgpool_recovery('/u01/app/pgpool4.2.5/etc/recovery_1st_stage', 'k8s01', '/data/pg13.4', '5432', 0, '5432')",,,"","client backend"

注意这部分：/data/pg13.4//u01/app/pgpool4.2.5/etc/recovery_1st_stage，配置中加了路径，然后C代码在执行时又默认添加了$PGDATA(见上面代码)，我们把recovery_1st_stage移到$PGDATA，取消配置文件中的路径，存在类似问题的还有pgpool_remote_start脚本，调整后重启系统,在线恢复正常运行。

3.2 解决replication slot "“k8s01"” does not exist
这个问题算是PGPool-II的BUG了，由于它采用了pg_basebackup来做故障恢复，把当前库的postgresql.auto.conf也同步了过去，内容如下：

# Do not edit this file manually!
# It will be overwritten by the ALTER SYSTEM command.
primary_conninfo = 'user=postgres passfile=''/home/postgres/.pgpass'' channel_binding=disable host=k8s01 port=5432 sslmode=disable sslcompression=0 ssl_min_protocol_version=TLSv1.2 gssencmode=disable krbsrvname=postgres target_session_attrs=any'

由于它的优先级比postgresql.conf配置要高，PGPool-II写入postgresql.conf的信息未起作用，这部分要修改recovery_1st_stage脚本，屏蔽postgresql.auto.conf中的相同信息，增加代码如下：

sed -i -e 's/primary_conninfo/# &/' -e 's/recovery_target_timeline/# &/' -e 's/restore_command/# &/' -e 's/primary_slot_name/# &/' ${DEST_NODE_PGDATA}/postgresql.auto.conf

系统重置，重新执行在线恢复，全部恢复正常。