pg_statsinfoからsyslog, textlogへの出力が停止し、autovacuum等の稼働情報が取得できなくなる

[itabashi-a]

環境

• OS : Red Hat Enterprise Linux 9.2
• PostgreSQL : 15.4
• pg-statsinfo : 15.3

※ 当方では上記環境で使用するため、調査・デバッグを行っております。
※ ここに記載した現象は、2025年6月時点の最新版 PostgreSQL v17.5 + pg_statsinfo 17.0でも発生することを確認しております。

現象
改行を含む長文のSQLが大量にPostgreSQLのログ(以下、csvlog)に出力される環境下において、textlogやsyslogに下記のログが出力され、以降、textlog, syslogへの出力が停止する事象が起きております。

2025-05-29 00:05:44 JST 9777 PG-00000 WARNING:  pg_statsinfo: cannot parse csvlog column 14: 2025-05-29 00:05:44.653 JST
2025-05-29 00:05:45 JST 9777 PG-00000 WARNING:  pg_statsinfo: cannot parse csvlog column 2:                     ) T
2025-05-29 00:05:45 JST 9777 PG-S0002 WARNING:  pg_statsinfo: could not read csvlog file "/var/log/postgres/postgresql-20250529_000000.csv": No such file or directory

さらに、textlog, syslogへの出力が停止した後に動作したautovacuum, autoanalyze, checkpoint等の、csvlogから読み込んでリポジトリに格納されるべき稼働情報が取得できなくなることも確認しております。
本事象は、「csvにこのログが出力されたら確実に発生する」というものは見つかっておらず、「改行を含む長文のSQLが大量にPostgreSQLのログに出力される」環境で多い時には1日数回発生します。

対応、もしくは回避策をマニュアルに記載いただけますと幸いです。

詳細
当方で調査した結果を記載します。

• csvlogの読込の失敗は、pg_statsinfod内のlogger_send, loggerスレッドの両方で発生します。
• loggerスレッドで発生すると、textlog, syslogへの出力が停止する事象が起きます。
• 当環境ではrepologへの登録を無効にしているため、logger_sendスレッドで現象が発生した場合の影響は調査しておりませんが、statsrepo.logテーブルへの登録が行われない事象が発生すると想定されます。
• PostgreSQLのログローテーションが行われると、csvlogの読込が再開します(loggerスレッドのみ確認)。
• PostgreSQLのログローテーションが行われる前にpg_statsinfoを再起動すると、csvlogの読み込みが停止した箇所から再開し、syslog, textlogに出力されるが、autovacuum等の稼働情報はリポジトリに登録されません。
• csvログのWARNING出力の1行目"cannot parse csvlog column 14"は、ソースコード logger_in.c の read_csv関数において、csvlogを読み込むfgets関数(logger_in.c 46行目)で失敗したことが分かっています。
  https://github.com/ossc-db/pg_statsinfo/blob/15.3/agent/bin/logger_in.c#L46
  ※ 当方が調査した範囲では、fgets関数が失敗したときのエラーステータス(errno)は、2が格納されていました。
• csvログのWARNING出力の2行目"cannot parse csvlog column 2"は、1行目のfgets関数失敗した後、csvlogの読み込みに失敗した次の行から読み込もうとしてread_csv関数で失敗し(logger_in.c 138行目)する。
  https://github.com/ossc-db/pg_statsinfo/blob/15.3/agent/bin/logger_in.c#L138
  その後のエラー処理でcsvlogをクローズするため、以降、textlog, syslogへの出力が停止すると認識しています。
  https://github.com/ossc-db/pg_statsinfo/blob/15.3/agent/bin/logger.c#L797

再現環境
本現象は、下記の条件で再現することを確認しております。

• PostgreSQL 15.4
• pg_statsinfo 15.3
• zabbix_agent2 zabbix-6.0.23 ※ zabbixでPostgreSQLを監視する設定を実施/改行を含む長文のSQLを実行する環境のために使用

PostgreSQLに追加で設定したパラメータは下記になります。

# Connections and Authentication
listen_addresses = '*'

# Write Ahead Log
synchronous_commit = 'local'
checkpoint_timeout = 1800
archive_mode = on
archive_command = 'test ! -f /var/lib/pgsql/15/archive/%f && cp %p /var/lib/pgsql/15/archive/%f'
restore_command = 'cp -p "/var/lib/pgsql/15/archive/%f" "%p"'

# Query Planning
random_page_cost = 1.1

# Error Reporting and Logging
log_destination = csvlog
log_directory = '/var/log/postgres'
log_filename = 'postgresql-%Y%m%d_%H%M%S.log'
log_min_messages = 'warning'
log_autovacuum_min_duration = 0
log_checkpoints = 'on'
log_connections = 'on'
log_disconnections = 'on'
log_lock_waits = 'on'
log_temp_files = 0
log_min_duration_statement = 0
log_statement = all
lc_messages = 'C'

# Run-time Statistics
track_io_timing = 'on'

# Client Connection Defaults
shared_preload_libraries = 'pg_stat_statements, pg_statsinfo'

# Lock Management
deadlock_timeout = '10s'

# pg_statsinfo
pg_statsinfo.textlog_min_messages = 'warning'
pg_statsinfo.syslog_min_messages = 'warning'
pg_statsinfo.textlog_line_prefix = '%t %p PG-%e '
pg_statsinfo.syslog_line_prefix = '%t %p PG-%e '
pg_statsinfo.repolog_min_messages = 'disable'
pg_statsinfo.target_server = 'dbname=statsinfo'
pg_statsinfo.repository_server = 'dbname=statsrepo'

追加情報を記載します。

想定原因
logger.cファイル内のlogger_next関数を追加で確認したところ、次がわかりました。
・read_csv関数で1行目の警告メッセージを出力した後、feof関数は1を返す(csvlogの末尾に達した)
・read_csv関数で2行目の警告メッセージを出力した後、feof関数は0を返す(csvlogの途中であった)ので、3行目の警告メッセージを出力した。

※ ログを再掲します。

2025-05-29 00:05:44 JST 9777 PG-00000 WARNING:  pg_statsinfo: cannot parse csvlog column 14: 2025-05-29 00:05:44.653 JST
2025-05-29 00:05:45 JST 9777 PG-00000 WARNING:  pg_statsinfo: cannot parse csvlog column 2:                     ) T
2025-05-29 00:05:45 JST 9777 PG-S0002 WARNING:  pg_statsinfo: could not read csvlog file "/var/log/postgres/postgresql-20250529_000000.csv": No such file or directory

上記警告が出力される流れは(1)→(2)→(3)であることから、(2)の処理が根本的な原因であると想定しております。
(1) 1行目の警告メッセージが出力された原因は、read_csv内のfgets関数が実行されたタイミングでcsvlogのファイルの末尾に達していたため、read_csv関数が失敗する。(その後のfeof関数でcsvlogの末尾に達した
(2) しかし、790行目でread_csvの成否にかかわらずcsvlogの読込進捗を示すcsv_offsetを進めている。
(3) 再度csvを読み込む際、「ファイルの末尾」と判断した(1)の後の行からcsvlogを読み込む。(1)が複数行のcsvレコードの途中で合った場合、後続処理で正しいcsvとして読めずに失敗する。
https://github.com/ossc-db/pg_statsinfo/blob/15.3/agent/bin/logger.c#L790

ご確認をお願いいたします。