pgpool

pgpoolのlog_destination

この話題は、pgpoolとCentOS8の話です。

pgpoolの設定の一つである「log_destination」はログの出力先を指定します。
設定値は、「stdder」、「syslog」、「stdder,syslog」の3種類です。

log_destinationを「stdder,syslog」に設定し、rsyslog.confをそれなりに設定し、これで/var/log/pgpool/pgpool.logにだけログが出力されると思ったら、/var/log/pgpool/pgpool.logにも、/var/log/messagesにも出力されていました。
log_destinationを「syslog」に設定して、思ったとおりの動作になりました。

「stdder,syslog」と設定すると、pgpoolはstdderにもsyslogにもログを出力します。
stdderに出力されたログは、systemdがjournaldに渡します。
journaldは渡されたログをrsyslogdに渡します。
# cat /etc/rsyslog.conf
<中略>
module(load="imjournal"             # provides access to the systemd journal
       StateFile="imjournal.state") # File to store the position in the journal

log_destinationを「stdder,syslog」に設定すると、「syslog」の設定がrsyslogd経由でログを書き込み、「stdder」の設定が、journald→rsyslogd経由でログを書き込む、動作になります。

log_destinationを「syslog」にしてログを保存する場合の設定は公式マニュアル、「stdder」にしてログを保存する場合はpgpool logging on centos 7 | Pierre Timmermansを参照するといいと思います。

Apache + pgpool + PostgreSQLで、Apacheがtimeoutで504を返すとき、PostgreSQLのクエリが残ったままになる

この文書はApache2.4.37とPostgreSQL11.7とpgpool4.1.1の話題です。

Apache + pgpool + PostgreSQLで、Apacheがtimeoutで504を返すとき、PostgreSQLのクエリが残ったままになることがあります。

ErogameScapeのApacheはtimeoutを120秒に設定しています。
時間のかかるクエリを実行して120秒を超えてしまうとApacheは504を返します。
このとき実行されたクエリがpsコマンドで見ると実行されっぱなしになっているように見えます。
[ap2@sakura ~]$ ps ax | grep 28908
 8134 pts/0    S+     0:00 grep --color=auto 28908
28908 ?        Ss     0:00 postgres: ap2 ap2 127.0.0.1(55878) UPDATE
このPostgreSQLのプロセスに対応するpgpoolのプロセスを確認するとidleまたはidle in transactionになります。
[ap2@sakura ~]$ ps ax | grep 27546
 8121 pts/0    S+     0:00 grep --color=auto 27546
27546 ?        S      0:00 pgpool: ap2 ap2 127.0.0.1(58634) idle in transaction
このまましておくと、PostgreSQLのクエリがテーブルをロックしたままになってしまっているので、pgpool + PostgreSQLの構成においてテーブルをロックしているPostgreSQLのSQLをキャンセルしたいの記事の方法でpgpoolのプロセスを殺します。

なぜこのような状態になってしまうのか分かりません…
解決方法は、Apacheのtimeoutの設定をのばす、クエリを見直してtimeout以内に収まるようにする、なのですが、根本的な解決方法ではないので困っております。

pgpool + PostgreSQLの構成においてテーブルをロックしているPostgreSQLのSQLをキャンセルしたい

この文書はPostgreSQL11.7とpgpool4.1.1の話題です。

なんらかの理由でテーブルをロックしたままのPostgreSQLのSQLをキャンセルしてロックを開放したい場合以下の関数を使います。


この関数は成功するとtrueを返すのですが、trueが返ってきたからといって、キャンセルできる(プロセスを終了できる)わけではありません。
以下に例を示します。
ap2=# select l.pid , a.backend_start from (select pid from pg_locks group by pid) l,pg_stat_activity a where l.pid=a.pid order by query_start;
  pid  |         backend_start
-------+-------------------------------
 10673 | 2020-05-06 14:06:57.721961+09
 18222 | 2020-05-06 15:52:12.091632+09
 28546 | 2020-05-06 16:30:04.77062+09
(3 rows)

ap2=# SELECT pg_cancel_backend(10673);
 pg_cancel_backend
-------------------
 t
(1 row)

ap2=# SELECT pg_cancel_backend(18222);
 pg_cancel_backend
-------------------
 t
(1 row)

ap2=# select l.pid , a.backend_start from (select pid from pg_locks group by pid) l,pg_stat_activity a where l.pid=a.pid order by query_start;
  pid  |         backend_start
-------+-------------------------------
 10673 | 2020-05-06 14:06:57.721961+09
 18222 | 2020-05-06 15:52:12.091632+09
 28546 | 2020-05-06 16:30:04.77062+09
(3 rows)
10673と18222のプロセスを終了したいのですが、終了できません。
pg_terminate_backend(pid int)を使うと終了できるのですが、pgpoolを使っている場合、pg_terminate_backendを使うとpgpoolがPostgreSQLを切り離すので、サービスが中断します。

ErogameScapeにおいて、上記のようにpg_cancel_backendがきかないのは以下のような状況のときのようでした。

Apacheにアクセス
php-fpmがpgpoolにクエリを発行
pgpoolがPostgreSQLにクエリを発行
クエリの実行に時間がかかる
一定時間たってもphp-fpmから応答がないのでApacheがtimeoutとしてユーザーに504を返す
このあとpsコマンドで確認すると
pgpoolはidleもしくはidle in transaction
PostgreSQLはSELECTだったりUPDATEだったりpgpoolが発行したSQLを実行している状態

以下、例を示します。
[root@sakura ap2]# cat /var/log/httpd/access_log | grep update
127.0.0.1 - - [08/May/2020:04:40:01 +0900] "GET /~ap2/ero/toukei_kaiseki/update_userreview_display_log.php HTTP/1.1" 504 247 "-" "Wget/1.19.5 (linux-gnu)" 60027802
127.0.0.1 - - [08/May/2020:04:41:02 +0900] "GET /~ap2/ero/toukei_kaiseki/update_userreview_display_log.php HTTP/1.1" 504 247 "-" "Wget/1.19.5 (linux-gnu)" 60060326
127.0.0.1 - - [08/May/2020:04:42:04 +0900] "GET /~ap2/ero/toukei_kaiseki/update_userreview_display_log.php HTTP/1.1" 200 462 "-" "Wget/1.19.5 (linux-gnu)" 6428
[root@sakura ap2]# cat /var/lib/pgsql/11/log/postgresql-Fri.log
2020-05-08 04:41:10.718 JST [28908] [ap2] LOG:  duration: 8271.792 ms  execute : UPDATE userreview SET display_unique_count = coalesce( display_unique_count , 0 ) + $1 WHERE uid = $2 AND game = $3 ;
ap2=# select * from (select pid from pg_locks group by pid) l,pg_stat_activity a where l.pid=a.pid order by query_start;
  pid  |  datid   | datname |  pid  | usesysid | usename | application_name | client_addr | client_hostname | client_port |
        backend_start         |          xact_start           |          query_start          |         state_change
  | wait_event_type | wait_event | state  | backend_xid | backend_xmin |
     query                                                         |  backend_type
-------+----------+---------+-------+----------+---------+------------------+-------------+-----------------+-------------+-
------------------------------+-------------------------------+-------------------------------+-----------------------------
--+-----------------+------------+--------+-------------+--------------+----------------------------------------------------
-------------------------------------------------------------------+----------------
 28908 | 10934808 | ap2     | 28908 |    16385 | ap2     |                  | 127.0.0.1   |                 |       55878 |
2020-05-08 04:41:01.103872+09 | 2020-05-08 04:41:02.407331+09 | 2020-05-08 04:41:02.446477+09 | 2020-05-08 04:41:02.446478+0
9 | Client          | ClientRead | active |    17877103 |              | UPDATE userreview SET display_unique_count = coales
ce( display_unique_count , 0 ) + $1 WHERE uid = $2 AND game = $3 ; | client backend
この状態で
SELECT pg_cancel_backend(28908);
しても、28908を終了させることができません。

28908を使っているpgpoolのプロセスを殺したところ、28908を終了させることができました。
pcp_proc_infoコマンドで28908を使っているpgpoolのプロセスIDを確認します。
[ap2@sakura ~]$ pcp_proc_info -h /var/run/postgresql/ -U pgpool | grep 28908
Password:
ap2 ap2 2020-05-08 04:36:00 2020-05-08 04:41:01 3 0 2 28908 1 27546 0
28908と27546のプロセスを確認します。
[ap2@sakura ~]$ ps ax | grep 27546
 8121 pts/0    S+     0:00 grep --color=auto 27546
27546 ?        S      0:00 pgpool: ap2 ap2 127.0.0.1(58634) idle in transaction
[ap2@sakura ~]$ ps ax | grep 28908
 8134 pts/0    S+     0:00 grep --color=auto 28908
28908 ?        Ss     0:00 postgres: ap2 ap2 127.0.0.1(55878) UPDATE
27546をkillします。
※確か、kill 27546では殺せなくて、kill -KILL 27546で殺しました。
これで、28908のプロセスも開放されて、ロックされていたテーブルもロックが解除されました。

※そもそも、なぜpostgresがSELECTやUPDATEのまま止まってしまうのかの原因は未だ分かりません…

failover_on_backend_error


failover_on_backend_errorをoffにすると、pgpoolがフェイルオーバーの処理をしてくれなくなるので、別の仕組みでフェイルオーバーの仕組みを実装する必要があります。

health_check_max_retreisを有効にするのは、ネットワークが不安定になることがあるので、health_checkのリトライをしたい場合であって、pgpoolのフェイルオーバーは依然として必要だと思いますので、onのままにすることが多いのでは無いかと思います。
※「health_check_max_retreisを有効にする場合は、failover_on_backend_errorを無効にするのが望ましい」理由が分かりませんでした…

あまり考えずにfailover_on_backend_errorをoffに設定したら、以下の事象が発生しサービスが中断しました。
以下pgpoolのログです。
May 31 23:10:44 erogamescape13 pgpool[12780]: [313206-1] 2019-05-31 23:10:44: pid 12780: LOG:  trying connecting to PostgreSQL server on "192.168.0.14:5432" by INET socket
May 31 23:10:44 erogamescape13 pgpool[12780]: [313206-2] 2019-05-31 23:10:44: pid 12780: DETAIL:  timed out. retrying...
May 31 23:10:54 erogamescape13 pgpool[12780]: [313207-1] 2019-05-31 23:10:54: pid 12780: LOG:  trying connecting to PostgreSQL server on "192.168.0.14:5432" by INET socket
May 31 23:10:54 erogamescape13 pgpool[12780]: [313207-2] 2019-05-31 23:10:54: pid 12780: DETAIL:  timed out. retrying...
May 31 23:11:04 erogamescape13 pgpool[12780]: [313208-1] 2019-05-31 23:11:04: pid 12780: LOG:  trying connecting to PostgreSQL server on "192.168.0.14:5432" by INET socket
May 31 23:11:04 erogamescape13 pgpool[12780]: [313208-2] 2019-05-31 23:11:04: pid 12780: DETAIL:  timed out. retrying...
May 31 23:11:14 erogamescape13 pgpool[12780]: [313209-1] 2019-05-31 23:11:14: pid 12780: LOG:  trying connecting to PostgreSQL server on "192.168.0.14:5432" by INET socket
May 31 23:11:14 erogamescape13 pgpool[12780]: [313209-2] 2019-05-31 23:11:14: pid 12780: DETAIL:  timed out. retrying...
May 31 23:11:24 erogamescape13 pgpool[12780]: [313210-1] 2019-05-31 23:11:24: pid 12780: LOG:  trying connecting to PostgreSQL server on "192.168.0.14:5432" by INET socket
May 31 23:11:24 erogamescape13 pgpool[12780]: [313210-2] 2019-05-31 23:11:24: pid 12780: DETAIL:  timed out. retrying...
May 31 23:11:34 erogamescape13 pgpool[12780]: [313211-1] 2019-05-31 23:11:34: pid 12780: LOG:  trying connecting to PostgreSQL server on "192.168.0.14:5432" by INET socket
May 31 23:11:34 erogamescape13 pgpool[12780]: [313211-2] 2019-05-31 23:11:34: pid 12780: DETAIL:  timed out. retrying...
May 31 23:11:37 erogamescape13 pgpool[12780]: [313212-1] 2019-05-31 23:11:37: pid 12780: LOG:  failed to connect to PostgreSQL server on "192.168.0.14:5432", getsockopt() detected error "Connection timed out"
May 31 23:11:37 erogamescape13 pgpool[12780]: [313213-1] 2019-05-31 23:11:37: pid 12780: LOG:  failed to create a backend 0 connection
May 31 23:11:37 erogamescape13 pgpool[12780]: [313213-2] 2019-05-31 23:11:37: pid 12780: DETAIL:  skip this backend because because failover_on_backend_error is off and we are in streaming replication mode and node is standby node
May 31 23:11:37 erogamescape13 pgpool[12780]: [313214-1] 2019-05-31 23:11:37: pid 12780: LOG:  master node 0 is down. Update master node to 1
May 31 23:11:37 erogamescape13 pgpool[12780]: [313215-1] 2019-05-31 23:11:37: pid 12780: LOG:  failback event detected
May 31 23:11:37 erogamescape13 pgpool[12780]: [313215-2] 2019-05-31 23:11:37: pid 12780: DETAIL:  restarting myself
May 31 23:11:38 erogamescape13 pgpool[13944]: [313288-1] 2019-05-31 23:11:38: pid 13944: ERROR:  unable to read message kind
May 31 23:11:38 erogamescape13 pgpool[13944]: [313288-2] 2019-05-31 23:11:38: pid 13944: DETAIL:  kind does not match between master(0) slot[0] (52)
health_check_max_retreisを3に設定していたのに、どうしてconnectingが6回timeoutしているのか分からないのですが、6回timeoutして、failed to create a backend 0 connectionと判定しています。
※ちなみにbackend0のPostgreSQLはprimaryでした。

ここで、backend 0を切り離して、事前に用意したフェイルオーバーのためのスクリプトをpgpoolが起動して、backend 1を昇格させる必要があるのですが、failover_on_backend_errorがoffなので、pgpoolは何もせず(skip this backend because because failover_on_backend_error is off)、でもpgpoolとしては、backend 1がprimaryだと判断して動き始めます(Update master node to 1)。

しかし、実際はbackend 1はstandbyのままなので、kind does not match between master(0) slot[0]となってPostgreSQLに接続出来ず、サービスが中断しました。

postmaster on DB node 1 was shutdown by administrative command

pgpoolで以下のログを出力してPostgreSQLが切り離されてしまう事象が発生しました。
May 28 04:40:03 erogamescape13 pgpool[12457]: [74016-2] 2019-05-28 04:40:03: pid 12457: DETAIL:  postmaster on DB node 1 was shutdown by administrative command
May 28 04:40:03 erogamescape13 pgpool[12457]: [74017-1] 2019-05-28 04:40:03: pid 12457: LOG:  received degenerate backend request for node_id: 1 from pid [12457]
PostgreSQLの方では以下のログを出力しています。
2019-05-28 04:40:01.414 JST [12646] FATAL:  terminating connection due to administrator command
このメッセージを発生させるような処理はしていない…(pg_terminate_backendでプロセスを終了させると出るそうですが、そのような処理はしていない…)ので、何が起きたのか謎です。

出来ることはPostgreSQLのログのレベルを深くして、同じ事象が出た時に何かログに記録されることを期待します。
具体的には以下のとおりログのレベルを変更しました。
[root@erogamescape13 log]# emacs /var/lib/pgsql/11/data/postgresql.conf

- client_min_messages = notice
+ client_min_messages = log

- log_min_messages = warning
+ log_min_messages = info

- log_min_error_statement = error
+ log_min_error_statement = warning

ここまでたどり着くのにpgpoolのソースをおってしまったので、そのおいかたを記録に残しておきます。※自分、C言語はわからないので、雰囲気だけでおいました。
find . -type f | grep .c$ | xargs grep -n "postmaster on DB node"
で、postmaster on DB node 1 was shutdown by administrative commandのメッセージがどこで出力されるか調べる。
./src/protocol/pool_process_query.c:4858:

				r = detect_postmaster_down_error(CONNECTION(backend, i), MAJOR(backend));
				if (r == SPECIFIED_ERROR)
				{
					ereport(LOG,
							(errmsg("reading and processing packets"),
							 errdetail("postmaster on DB node %d was shutdown by administrative command", 
pool_process_query.cで、detect_postmaster_down_error関数の結果がSPECIFIED_ERRORの場合にpostmaster on DB node %d was shutdown by administrative commandが出る。
detect_postmaster_down_error関数を探して見てみる。
detect_postmaster_down_error(POOL_CONNECTION * backend, int major)
{
	int			r = detect_error(backend, ADMIN_SHUTDOWN_ERROR_CODE, major, 'E', false);

	return r;
}
SPECIFIED_ERRORがなんなのかわからないけど、detect_errorの引数にADMIN_SHUTDOWN_ERROR_CODEが与えられている。
ADMIN_SHUTDOWN_ERROR_CODEを探す。
#define ADMIN_SHUTDOWN_ERROR_CODE "57P01"
ADMIN_SHUTDOWN_ERROR_CODEは57P01のこと。
57P01をgoogleで検索すると以下のWebページがひっかかる。
57P01はadmin_shutdownのこと。

detect_error関数を見てみる。
detect_error(POOL_CONNECTION * backend, char *error_code, int major, char class, bool unread)
{
	int			is_error = 0;
	char		kind;
	int			readlen = 0,
				len;
	static char buf[8192];		/* memory space is large enough */
	char	   *p,
			   *str;

	if (pool_read(backend, &kind, sizeof(kind)))
		return -1;
	readlen += sizeof(kind);
	p = buf;
	memcpy(p, &kind, sizeof(kind));
	p += sizeof(kind);

	ereport(DEBUG5,
			(errmsg("detect error: kind: %c", kind)));


	/* Specified class? */
	if (kind == class)
	{
		/* read actual message */
		if (major == PROTO_MAJOR_V3)
		{
			char	   *e;

			if (pool_read(backend, &len, sizeof(len)) < 0)
				return -1;
			readlen += sizeof(len);
			memcpy(p, &len, sizeof(len));
			p += sizeof(len);

			len = ntohl(len) - 4;
			str = palloc(len);

			pool_read(backend, str, len);
			readlen += len;

			if (readlen >= sizeof(buf))
				ereport(ERROR,
						(errmsg("unable to detect error"),
						 errdetail("not enough space in buffer")));

			memcpy(p, str, len);

			/*
			 * Checks error code which is formatted 'Cxxxxxx' (xxxxxx is error
			 * code).
			 */
			e = str;
			while (*e)
			{
				if (*e == 'C')
				{				/* specified error? */
					is_error = (strcmp(e + 1, error_code) == 0) ? SPECIFIED_ERROR : 0;
					break;
				}
				else
					e = e + strlen(e) + 1;
			}
			pfree(str);
何をしてるのか詳細は分からないですが…、多分、PostgreqSQLのバックエンドから情報を引っ張ってきてエラーだったら「Cxxxxxx」という文字が取得でして、xxxxxxのところにエラーコードが入るのかなと思う。
xxxxxxは今回は57P01が入ってくるのかな…と思う。

以上から、PgpoolはPostgreSQLから57P01を受け取っただけ、と思いました。
その後、PostgreSQLのログを確認し
2019-05-28 04:40:01.414 JST [12646] FATAL:  terminating connection due to administrator command
を発見しました。
※ちなみに、一度、PostgreSQLのログを見たのですが、ログを見逃していて…、Pgpool側の問題かと思ってしまいました。凡ミスです…

スイッチオーバーなのにpg_rewind/pg_basebackupが必要になってしまう

ErogameScapeではpgpoolを使って負荷分散、PostgreSQL障害時の切り替えを実施しています。
PostgreSQLは同期レプリケーションでprimary、standbyの2台構成です。

primaryを正常に停止して(pg_ctl stopして)、standbyを昇格させた(pg_ctl promote)場合、旧primaryはrecovery.confに新primaryを指定して起動すれば、ちゃんとレプリケーションが開始されます。

ところが、pgpoolでfailover_commandとして、
1. 非同期モードに設定を変更(postgresql.confのsynchronous_standby_namesを''にしてreload)
2. standbyを昇格(pg_ctl promote)
というスクリプトを指定し、primaryをpg_ctl stopさせた、旧primaryに適切なrecovery.confを書いて起動させたにも関わらず、レプリケーションが開始出来ず、pg_rewindが必要になってしまいました。

ちゃんとした理由は未だに分からないのですが、おそらく、primaryのpg_ctl stopが完全に終わる前に、pgpoolがstandbyをpg_ctl promoteしてしまうからではないか…と想定しました。
※primaryをちゃんとstopせずに、standbyをpg_ctl promoteすると、経験上、多くの場合で、pg_rewindかpg_basebackupが必要になります。

そこで、failover_commandのスクリプトにsleepを10秒(根拠はありません…)いれてみたら、想定通りスイッチオーバーとしての動作となりました。
以下failover_commandのスクリプトです。
#! /bin/sh -x
# Execute command by failover.
# special values:  %d = node id
#                  %h = host name
#                  %p = port number
#                  %D = database cluster path
#                  %m = new master node id
#                  %M = old master node id
#                  %H = new master node host name
#                  %P = old primary node id
#                  %R = new master database cluster path
#                  %r = new master port number
#                  %% = '%' character

falling_node=$1          # %d
old_primary=$2           # %P
new_primary=$3           # %H
pgdata=$4                # %R
old_hostname=$5          # %h

pghome=/usr/pgsql-11
log=/var/log/pgpool/failover.log

date >> $log
echo "failed_node_id=$falling_node old_primary=$old_primary new_primary=$new_primary old_hostname=$old_hostname UID=$UID" >> $log

if [ $falling_node = $old_primary ]; then
    echo "failed_node_id=master" >> $log
    if [ $UID -eq 0 ]; then
        su postgres -c "ssh -T postgres@$new_primary $pgdata/synchronous_standby_names_change.sh"
        su postgres -c "ssh -T postgres@$new_primary $pghome/bin/pg_ctl reload -D $pgdata"
        sleep 10
        su postgres -c "ssh -T postgres@$new_primary $pghome/bin/pg_ctl promote -D $pgdata"
        su postgres -c "ssh -T postgres@$old_hostname cp -p $pgdata/recovery.conf.for.$old_hostname $pgdata/recovery.conf"
    else
        ssh -T postgres@$new_primary $pgdata/synchronous_standby_names_change.sh
        ssh -T postgres@$new_primary $pghome/bin/pg_ctl reload -D $pgdata
        sleep 10
        ssh -T postgres@$new_primary $pghome/bin/pg_ctl promote -D $pgdata
        ssh -T postgres@$old_hostname cp -p $pgdata/recovery.conf.for.$old_hostname $pgdata/recovery.conf
    fi
    exit 0;
else
    echo "failed_node_id=standby" >> $log
    if [ $UID -eq 0 ]; then
        su postgres -c "ssh -T postgres@$new_primary $pgdata/synchronous_standby_names_change.sh"
        su postgres -c "ssh -T postgres@$new_primary $pghome/bin/pg_ctl reload -D $pgdata"
    else
        ssh -T postgres@$new_primary $pgdata/synchronous_standby_names_change.sh
        ssh -T postgres@$new_primary $pghome/bin/pg_ctl reload -D $pgdata
    fi
fi;
exit 0;
synchronous_standby_names_change.shは、同期レプリケーションを非同期レプリケーションにするために、postgresql.confを書き換えるスクリプトです。
sed -i -e "/synchronous_standby_names/c\#synchronous_standby_names = 'sby'      # standby servers that provide sync rep" /var/lib/pgsql/11/data/postgresql.conf


could not fork new process for connection: Resource temporarily unavailable

PostgreSQLで以下のログを出力した場合、バックエンド・プロセスをforkできていません。
2019-05-26 19:58:26.308 JST [20730] LOG:  could not fork new process for connection: Resource temporarily unavailable
2019-05-26 19:58:27.313 JST [20730] LOG:  could not fork new process for connection: Resource temporarily unavailable
2019-05-26 19:58:27.315 JST [20730] LOG:  could not fork new process for connection: Resource temporarily unavailable
2019-05-26 19:58:28.026 JST [20730] LOG:  could not fork new process for connection: Resource temporarily unavailable
pgpoolを使用している場合、pgpool側では以下のログが出力されます。 ※PostgreSQLへのヘルスチェック機能を有効にしている場合に出力されると思います。
May 26 19:58:27 erogamescape13 pgpool[1696]: [159-1] 2019-05-26 19:58:27: pid 1696: ERROR:  failed to authenticate
May 26 19:58:27 erogamescape13 pgpool[1696]: [159-2] 2019-05-26 19:58:27: pid 1696: DETAIL:  invalid authentication message response type, Expecting 'R' and received 'E'
ヘルスチェックのリトライが指定の回数失敗すると、フェイルバック機能が動きます。
May 26 19:58:28 erogamescape13 pgpool[26104]: [9-1] 2019-05-26 19:58:28: pid 26104: LOG:  health check failed on node 0 (timeout:0)
May 26 19:58:28 erogamescape13 pgpool[26104]: [10-1] 2019-05-26 19:58:28: pid 26104: LOG:  received degenerate backend request for node_id: 0 from pid [26104]
バックエンド・プロセスをfork出来ない理由は、ErogameScapeの場合、プロセス数の上限に達してしまって、プロセスを生成できないことが原因でした。
プロセス数の上限は以下のコマンドで確認可能です。
[root@erogamescape13 ap2]# su - postgres
-bash-4.1$ ulimit -u
1024
postgresユーザーのプロセス上限数が知りたかったので、postgresユーザーでulimitを実行しています。
今、動いているpostmasterのpostgresユーザーのプロセス数の上限を知りたい場合は、まずpostmasterのプロセスIDを調べ
[ap2@erogamescape14 ~]$ ps aux | grep postmaster
ap2       5692  0.0  0.0 103336   900 pts/2    S+   20:45   0:00 grep postmaster
postgres 27012  0.1  0.9 4595684 158676 ?      S    20:11   0:03 /usr/pgsql-11/bin/postmaster -D /var/lib/pgsql/11/data
cat /proc/プロセスID/limitsを見ます。
[root@erogamescape14 ap2]# cat /proc/27012/limits
Limit                     Soft Limit           Hard Limit           Units
Max processes             2048                 63695                processes
Max open files            1024                 4096                 files
ErogameScapeのOSはCentOS6です。
CentOS6のデフォルトのMax processesの上限は1024です。
PostgreSQLのmax_connectionsの数だけ、バックエンドプロセスが生成されれる可能性があります。
ErogameScapeではmax_connectionsを1200に設定しているのですが、いろいろありまして、postgresユーザーのプロセスが1024を超えてしまい、バックエンドプロセスが生成できずcould not fork new process for connectionを出力していました。

Max processesの上限を変更するため、以下の通り/etc/security/limits.d/90-nproc.confを書き換えて、postgreSQLを再起動しました。
※この方法だと他のユーザーも全部書き換わってしまうので…おそらく /etc/init.d/postgresql-11にulimitコマンドで上限を変更するコマンドを追加するのが妥当な気もするのですが、セオリーが分かりませんでした…
# emacs /etc/security/limits.d/90-nproc.conf

- *          soft    nproc     1024
+ *          soft    nproc     2048

watchdog exec interface up/down command failed その2

pgpoolのwatchdog機能をonにし、pgpoolを起動したら、arpingコマンドの実行に失敗したというログが残りました。
[pgpool@erogamescape14 ~]$ /usr/local/pgpool-II-4.0.4/bin/pgpool -d -n > /dev/null 2>&1 &

Apr 27 22:51:46 erogamescape14 pgpool[31446]: [38-1] 2019-04-27 22:51:46: pid 31446: DEBUG:  watchdog exec interface up/down command failed
Apr 27 22:51:46 erogamescape14 pgpool[31446]: [38-2] 2019-04-27 22:51:46: pid 31446: DETAIL:  'sudo arping -U $_IP_$ -w 1' failed. exit status: 2
Apr 27 22:51:46 erogamescape14 pgpool[31446]: [39-1] 2019-04-27 22:51:46: pid 31446: LOG:  failed to acquire the delegate IP address
Apr 27 22:51:46 erogamescape14 pgpool[31446]: [39-2] 2019-04-27 22:51:46: pid 31446: DETAIL:  'if_up_cmd' failed
Apr 27 22:51:46 erogamescape14 pgpool[31446]: [40-1] 2019-04-27 22:51:46: pid 31446: WARNING:  watchdog escalation failed to acquire delegate IP
arpingコマンドを実行した結果は以下のとおりです。
[pgpool@erogamescape14 ~]$ sudo arping -U 192.168.0.101 -w 1
Interface "eth0" is down
ErogameScapeのサーバーはeth0は使用しておらず、eth1だけを使用しています。
[pgpool@erogamescape14 ~]$ ifconfig -a
eth0      Link encap:Ethernet  HWaddr 00:24:8C:FC:29:1E
          BROADCAST MULTICAST  MTU:1500  Metric:1
          RX packets:0 errors:0 dropped:0 overruns:0 frame:0
          TX packets:0 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:1000
          RX bytes:0 (0.0 b)  TX bytes:0 (0.0 b)
          Interrupt:17

eth1      Link encap:Ethernet  HWaddr 00:1B:21:CE:8C:22
          inet addr:192.168.0.14  Bcast:192.168.0.255  Mask:255.255.255.0
          inet6 addr: fe80::21b:21ff:fece:8c22/64 Scope:Link
          UP BROADCAST RUNNING MULTICAST  MTU:1500  Metric:1
          RX packets:3514319869 errors:2 dropped:450 overruns:0 frame:2
          TX packets:3390163522 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:1000
          RX bytes:1709446725964 (1.5 TiB)  TX bytes:1194077098242 (1.0 TiB)
          Interrupt:17 Memory:feae0000-feb00000

lo        Link encap:Local Loopback
          inet addr:127.0.0.1  Mask:255.0.0.0
          inet6 addr: ::1/128 Scope:Host
          UP LOOPBACK RUNNING  MTU:65536  Metric:1
          RX packets:13606420638 errors:0 dropped:0 overruns:0 frame:0
          TX packets:13606420638 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:0
          RX bytes:3248906958354 (2.9 TiB)  TX bytes:3248906958354 (2.9 TiB)
pgpool.confのarping_cmdを以下のように書き換えて解決しました。
arping_cmd = 'sudo arping -U $_IP_$ -w 1'

arping_cmd = 'sudo arping -U $_IP_$ -w 1 -I eth1'

watchdog exec interface up/down command failed その1

[環境]
pgpool-4.0.4

[現象]
pgpoolの起動時に-nオプションをつけないと、if_up_cmdが失敗する

[原因]
分かりません…、私のやり方が悪いのか、バグなのかすら分からないので、あまりよろしくないのですが、とりあえず-nをつけて起動することにします。

[詳細]
pgpoolはWatchdog機能をONにすると、冗長構成をとることができます。
いろいろ設定し、pgpoolを-nオプションなしで立ち上げた場合、if_up_cmd、pgpoolのための仮想IPアドレスをIFに追加するコマンドが失敗します。
デバッグモードで立ち上げてもなぜ失敗しているかの記録がないのでなぜ失敗するのか分かりません。
[pgpool@erogamescape14 ~]$ /usr/local/pgpool-II-4.0.4/bin/pgpool -d

Apr 27 22:49:21 erogamescape14 [29985]: [37-1] 2019-04-27 22:49:21: pid 29985: DEBUG:  watchdog exec interface up/down command failed
Apr 27 22:49:21 erogamescape14 [29985]: [37-2] 2019-04-27 22:49:21: pid 29985: DETAIL:  'sudo ip addr add $_IP_$/24 dev eth1 label eth1:0' failed. exit status: 1
Apr 27 22:49:21 erogamescape14 [29985]: [38-1] 2019-04-27 22:49:21: pid 29985: LOG:  failed to acquire the delegate IP address
Apr 27 22:49:21 erogamescape14 [29985]: [38-2] 2019-04-27 22:49:21: pid 29985: DETAIL:  'if_up_cmd' failed
Apr 27 22:49:21 erogamescape14 [29985]: [39-1] 2019-04-27 22:49:21: pid 29985: WARNING:  watchdog escalation failed to acquire delegate IP
-nオプションをつけると、成功します。
[pgpool@erogamescape14 ~]$ /usr/local/pgpool-II-4.0.4/bin/pgpool -d -n > /dev/null 2>&1 &

Apr 27 22:51:46 erogamescape14 pgpool[31446]: [37-1] 2019-04-27 22:51:46: pid 31446: DEBUG:  watchdog exec interface up/down command: 'sudo ip addr add $_IP_$/24 dev eth1 label eth1:0' succeeded

理由はわからないですが、-nをつけてpgpoolを起動することにしました。
pgpoolの

pcp_attach_node: invalid option -- 'p'

ErogameScapeの現用サーバーにpgpool-4.0.4をソースからインストールして、pcp_attach_nodeを実行したところ以下のように、-pオプションはないと表示されました。
[ap2@erogamescape14 ~]$ pcp_attach_node -p 8898 -U pgpool 1
pcp_attach_node: invalid option -- 'p'
pcp_attach_node - attach a node from pgpool-II

Usage: pcp_attach_node [-d] timeout hostname port# username password nodeID
Usage: pcp_attach_node -h

  -d       - enable debug message (optional)
  timeout  - connection timeout value in seconds. command exits on timeout
  hostname - pgpool-II hostname
  port#    - pgpool-II port number
  username - username for PCP authentication
  password - password for PCP authentication
  nodeID   - ID of a node to be attached
  -h       - print this help
テストサーバーでは問題なく動いていたので、現用サーバーの問題だと思いました。
そこで「どのpcp_attach_nodeを実行しているか」を確認しました。
[ap2@erogamescape14 ~]$ which pcp_attach_node
/usr/local/bin/pcp_attach_node
ErogameScapeはpgpoolを追える範囲では2.3.3の頃から使っていて、いろいろなverのpcp_attach_nodeが格納されています。
[root@erogamescape14 pgpool]# find / -name pcp_attach_node
中略
/usr/local/pgpool-II-3.5.1/bin/pcp_attach_node
/usr/local/pgpool-II-3.6.0/bin/pcp_attach_node
/usr/local/pgpool-II-3.3.1/bin/pcp_attach_node
/usr/local/pgpool-II-4.0.4/bin/pcp_attach_node
/usr/local/bin/pcp_attach_node
/usr/local/bin/pcp_attach_nodeがいったいいつのverのpcp_attach_nodeなのか分かりません…
[ap2@erogamescape14 ~]$ /usr/local/pgpool-II-4.0.4/bin/pcp_attach_node -p 8898 -U pgpool 1
と実行して、ちゃんと動きました。
記事検索