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側の問題かと思ってしまいました。凡ミスです…
