PostgreSQLログのエラーレベルは場合によって引き上げられることがある

PostgreSQLのエラーレベルはメッセージごとに固定だと長らく勘違いしていた話。

マスタ接続失敗時のエラー

Streaming Replication構成でスタンバイから以下のようなメッセージがログに出力されていました。

FATAL: could not connect to the primary server: could not connect to server: No route to host

このメッセージが出たときにはマスタを落としていたので、メッセージが出ること自体は問題ではないですが、接続失敗でFATALになることがやや気になったので、調査しました。

ソースコード上だとFATALではなくERROR ?

メッセージでgrepすると、出力している場所は特定できました。

src/backend/replication/libpqwalreceiver/libpqwalreceiver.c

113     streamConn = PQconnectdbParams(keys, vals, /* expand_dbname = */ true);
114     if (PQstatus(streamConn) != CONNECTION_OK)
115         ereport(ERROR,
116                 (errmsg("could not connect to the primary server: %s",
117                         PQerrorMessage(streamConn))));
118 }

が、ERRROR？

いろいろ悩みましたが、結論はシンプルでした。

PostgreSQLの状態によってはエラーレベルが引き上げられることがある

知らなかった。。。

エラーメッセージを出力するための関数であるereport()の内部を追っていくと、以下のような箇所がありました。

src/postgres/src/backend/utils/error/elog.c

 235     /*
 236      * Check some cases in which we want to promote an error into a more
 237      * severe error.  None of this logic applies for non-error messages.
 238      */
 239     if (elevel >= ERROR)
 240     {
 241         /*
 242          * If we are inside a critical section, all errors become PANIC
 243          * errors.  See miscadmin.h.
 244          */
 245         if (CritSectionCount > 0)
 246             elevel = PANIC;
 247
 248         /*
 249          * Check reasons for treating ERROR as FATAL:
 250          *
 251          * 1. we have no handler to pass the error to (implies we are in the
 252          * postmaster or in backend startup).
 253          *
 254          * 2. ExitOnAnyError mode switch is set (initdb uses this).
 255          *
 256          * 3. the error occurred after proc_exit has begun to run.  (It's
 257          * proc_exit's responsibility to see that this doesn't turn into
 258          * infinite recursion!)
 259          */
 260         if (elevel == ERROR)
 261         {
 262             if (PG_exception_stack == NULL ||
 263                 ExitOnAnyError ||
 264                 proc_exit_inprogress)
 265                 elevel = FATAL;
 266         }

つまり、CriticalSectionの中（大抵はWALを扱っている処理中）だとERRORレベルからPANICへと強制的に変更され、そうでなくても以下の3つの条件のいずれかに該当する場合はERRORレベルからFATALへの強制的に変更されます。

1. エラーを渡すハンドラが存在しない = postmasterの内部処理でのエラー、もしくはバックエンドプロセスの初期化時のエラー
2. ExitOnAnyErrorフラグが立っているとき（initdbが該当）
3. proc_exitが開始した後のエラー = 何らかのエラーが発生して異常終了しようとしているときに更にエラーが発生した場合

今回の場合は、wal receiverプロセスの初期化時にエラーが発生したので1.が該当した結果、通常はERRORレベルで出力されるメッセージがFATALで出力されていた、というわけでした。

参考. PostgreSQLの出すログのメッセージのレベル

深刻度	使用方法	syslog	eventlog
DEBUG1..DEBUG5	開発者が使用する連続的かつより詳細な情報を提供します。	DEBUG	INFORMATION
INFO	VACUUM VERBOSEの出力などの、ユーザによって暗黙的に要求された情報を提供します。	INFO	INFORMATION
NOTICE	長い識別子の切り詰めに関する注意など、ユーザの補助になる情報を提供します。	NOTICE	INFORMATION
WARNING	トランザクションブロック外でのCOMMITの様な、ユーザへの警告を提供します。	NOTICE	WARNING
ERROR	現在のコマンドを中断させる原因となったエラーを報告します。	WARNING	ERROR
LOG	チェックポイントの活動の様な、管理者に関心のある情報を報告します。	INFO	INFORMATION
FATAL	現在のセッションを中断させる原因となったエラーを報告します。	ERR	ERROR
PANIC	全てのデータベースセッションを中断させる原因となったエラーを報告します。	CRIT	ERROR

http://www.postgresql.jp/document/current/html/runtime-config-logging.html

表 18-1. メッセージ深刻度レベル
より引用