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