rsyslog で PostgreSQL のログを別ファイルに分けるには

この記事は [PostgreSQL Advent Calendar 2024](https://qiita.com/advent-calendar/2024/postgresql) と [SRA Advent Calendar 2024](https://qiita.com/advent-calendar/2024/sra) の 23 日目です。

PostgreSQL にはログの設定がいろいろありますが、ログの内容に応じてファイルを分ける機能はなく、それを行うには外部プログラムを使う必要があります。この記事では rsyslog で PostgreSQL のログを別ファイルに分ける方法を紹介します。説明は Rocky Linux 9.4 上で PostgreSQL 17.2 のサービスを起動した状態を前提とします。

## rsyslog でログを取る

rsyslog でログを取るには、まず、PostgreSQL の設定を行います。PostgreSQL では、デフォルトでログを標準エラーに出力し、ログ取得コレクタでファイルにリダイレクトするので、syslog でログを取るように設定します。

```config:$PGDATA/postgresql.conf
log_destination = 'syslog'
logging_collector = off

#syslog_facility = 'LOCAL0'
#syslog_ident = 'postgres'
syslog_sequence_numbers = off
syslog_split_messages = off

log_line_prefx = '%q%u@%d '
```

パラメータの説明は以下です。

| パラメータ名 | 説明 |
|-|-|
| `log_destination` | ログ出力先。syslog の場合は `syslog` |
| `logging_collector` | ログ取得コレクタを起動するか？syslog では不要なので `off` |
| `syslog_facility` | syslog のログ種類を表すファシリティ。`LOCAL0` から `LOCAL7` のいずれか。ほかのプログラムと重複しなければ、デフォルトでよし |
| `syslog_ident` | syslog のログ識別子。同じファイルに出力のほかのプログラムと重複しなければ、デフォルトでよし |
| `syslog_sequence_numbers` | syslog で重複ログの省略を防ぐため、ログに通し番号を振るか？rsyslog では、デフォルトで省略しないので、不要な情報を出力しないように `off` |
| `syslog_split_messages` | syslog でログを複数行に分けるか？ログが複数行だと、フィルタリングできないので `off`。rsyslog では、ログ最大長がデフォルトで 8kB なので、それを越える場合は最大長を増やすか、`on` にする必要あり |
| `log_line_prefix` | ログ行頭に付ける情報。初期値は `%m [%p] `。タイムスタンプ `%m` と PID `%p` は rsyslog でもデフォルトで出力し、重複するので不要。代わりにデータベース接続を伴う場合のみ `%q`、ユーザ名 `%u` とデータベース名 `%d` を付けるように `%q%u@%d ` &nbsp; |

次に、rsyslog の設定を行います。rsyslog では、デフォルトで `/var/log/messages` ファイルにログを出力するので、別ファイルに出力するように設定します。rsyslog の設定は `/etc/rsyslog.conf` ファイルで行いますが、`/etc/rsyslog.d` ディレクトリに拡張子 `.conf` のファイルがあれば、そこから設定を読み込んでくれるので、PostgreSQL 向けの設定は `postgresql.conf` ファイルで行うことにします。

```config:/etc/rsyslog.d/postgresql.conf
if $syslogfacility-text == "LOCAL0" then {
  action(type="omfile" file="/var/log/postgresql/main.log")
  stop
}
```

`if` 文でファシリティ `$syslogfacility-text` が `LOCAL0` かをチェックし、`action` でファイル出力の `omfile` モジュールを使ってログを `/var/log/postgresql/main.log` ファイルに出力し、`stop` でほかのファイルに重複して出力しないように止めています。

最後に、ログ出力先のディレクトリを作成し、rsyslog と PostgreSQL のサービスを再起動し、rsyslog を通じてログが出力されるかを確認します。

```shell-session
$ sudo mkdir /var/log/postgresql
$ sudo systemctl restart rsyslog
$ sudo systemctl restart postgresql-17
$ sudo tail /var/log/postgresql/main.log
Dec 20 11:07:57 node-1 postgres[5418]: LOG:  ending log output to stderr#012HINT:  Future log output will go to log destination "syslog".
Dec 20 11:07:57 node-1 postgres[5418]: LOG:  starting PostgreSQL 17.2 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 11.5.0 20240719 (Red Hat 11.5.0-2), 64-bit
Dec 20 11:07:57 node-1 postgres[5418]: LOG:  listening on IPv6 address "::1", port 5432
Dec 20 11:07:57 node-1 postgres[5418]: LOG:  listening on IPv4 address "127.0.0.1", port 5432
Dec 20 11:07:57 node-1 postgres[5418]: LOG:  listening on Unix socket "/run/postgresql/.s.PGSQL.5432"
Dec 20 11:07:57 node-1 postgres[5418]: LOG:  listening on Unix socket "/tmp/.s.PGSQL.5432"
Dec 20 11:07:57 node-1 postgres[5421]: LOG:  database system was shut down at 2024-12-20 11:07:57 JST
Dec 20 11:07:57 node-1 postgres[5418]: LOG:  database system is ready to accept connections
```

これで rsyslog でログを取る設定は完了です。

監査ログを [pgAudit](https://github.com/pgaudit/pgaudit) で取っている場合、[pgAudit Log to File](https://github.com/fmbiete/pgauditlogtofile) で別ファイルに分けることもできます。

## 監査ログを別ファイルに分ける

監査ログとはシステムへのアクセスや操作を記録したログで、PostgreSQL でもデータベース接続・切断、実行された SQL をログに出力できます。

監査ログを別ファイルに分けるには、まず、PostgreSQL の設定を行います。データベース接続・切断、実行された SQL をログに出力するように設定します。

```config:$PGDATA/postgresql.conf
log_connections = on
log_disconnections = on
log_statement = 'all'
```

パラメータの説明は以下です。

| パラメータ名 | 説明 |
|-|-|
| `log_conenctions` | データベース接続をログに出力するか？出力するように `on` |
| `log_disconnections` | データベース切断をログに出力するか？出力するように `on` |
| `log_statement` | 実行された SQL をログに出力するか？すべて出力するように `all` |

次に、rsyslog の設定を行います。監査ログを `/var/log/postgresql/audit.log` ファイルに出力するように設定します。

```config:/etc/rsyslog.d/postgresql.conf
if $syslogfacility-text == "LOCAL0" then {
  if re_match($msg, "^.*@.* LOG:  (connection|disconnection|statement|execute).*: ") then
    action(type="omfile" file="/var/log/postgresql/audit.log")
  else
    action(type="omfile" file="/var/log/postgresql/main.log")
  stop
}
```

2 つ目の `if` 文でログ `$msg` が監査ログかをチェックするため、`re_match` 関数を使って正規表現でパターンマッチし、ログを `/var/log/postgresql/audit.log` ファイルに出力しています。

ログは言語によって異なりますが、監査ログに限って言えば、基本的にバージョン間での違いはありません。ログの言語は `lc_messages` パラメータで変更もできます。`syslog_sequence_numbers`、`syslog_split_messages` パラメータのいずれかが `on` だと、ログ行頭に `[通し番号-行番号]` が付きます。`syslog_split_messages` パラメータが `on` だと、ログが複数行に分かれるので、1 行目はパターンマッチできますが、2 行目以降はできません。

最後に、rsyslog と PostgreSQL のサービスをそれぞれ再起動、再読み込みし、データベースに接続し、SQL を実行し、そのログが別ファイルに出力されるかを確認します。PostgreSQL は変更に再起動が不要なパラメータのみなので、再読み込みで反映できます。

```shell-session
$ sudo systemctl restart rsyslog
$ sudo systemctl reload postgresql-17
$ psql -U postgres -d postgres -c "SELECT 1"
 ?column?
----------
        1
(1 行)

$ sudo tail /var/log/postgresql/main.log
(省略)
Dec 20 11:09:38 node-1 postgres[5418]: LOG:  received SIGHUP, reloading configuration files
Dec 20 11:09:38 node-1 postgres[5418]: LOG:  parameter "log_connections" changed to "on"
Dec 20 11:09:38 node-1 postgres[5418]: LOG:  parameter "log_disconnections" changed to "on"
Dec 20 11:09:38 node-1 postgres[5418]: LOG:  parameter "log_statement" changed to "all"
$ sudo tail /var/log/postgresql/audit.log
Dec 20 11:10:16 node-1 postgres[5461]: [unknown]@[unknown] LOG:  connection received: host=[local]
Dec 20 11:10:16 node-1 postgres[5461]: postgres@postgres LOG:  connection authenticated: user="postgres" method=trust (/var/lib/pgsql/17/data/pg_hba.conf:117)
Dec 20 11:10:16 node-1 postgres[5461]: postgres@postgres LOG:  connection authorized: user=postgres database=postgres application_name=psql
Dec 20 11:10:16 node-1 postgres[5461]: postgres@postgres LOG:  statement: SELECT 1
Dec 20 11:10:16 node-1 postgres[5461]: postgres@postgres LOG:  disconnection: session time: 0:00:00.004 user=postgres database=postgres host=[local]
```

これで監査ログを別ファイルに分ける設定は完了です。

## データベースごとにログファイルを分ける

データベースごとにログファイルを分けるには、rsyslog の設定を行います。ログをデータベースと同じ名前のファイルに出力するように設定します。

```config:/etc/rsyslog.d/postgresql.conf
template(name="myfile" type="string" string="/var/log/postgresql/%$.db%.log")
if $syslogfacility-text == "LOCAL0" then {
  set $.db = re_extract($msg, "^.*@(\\w*) ", 0, 1, "main");
  action(type="omfile" dynafile="myfile")
  stop
}
```

ログのファイルパスを動的に生成するため、`template` でファイルパスのファイル名の部分にデータベース名を埋め込むテンプレートを作成しています。テンプレート作成は `if` 文の外側で行う必要があります。

`set` でローカル変数 `$.db` にデータベース名をセットするため、`re_extract` 関数を使って正規表現でログ `$msg` からデータベース名を抽出しています。ローカル変数名は最初に `$.` を付け、`set` は最後に `;` を付ける必要があります。

`re_extract` 関数の引数は 1 つ目が対象文字列、2 つ目が正規表現パターン、3 つ目は何番目のマッチ結果を返すか、4 つ目はマッチ結果から何番目のサブマッチ結果を返すか、5 つ目はマッチしなかった場合に返す文字列を指定します。マッチ、サブマッチ結果の何番目かは 0 から始まります。サブマッチ結果はカッコで囲んだ部分で、0 番目はマッチ結果全体となります。
`action` で `omfile` モジュールを使ってログをファイルに出力していますが、動的なファイルパスの場合は `dynafile` にテンプレートを指定します。 

最後に、rsyslog のサービスを再起動し、`postgres`、`template1` データベースでそれぞれ SQL を実行し、そのログがデータベースごとに出力されるかを確認します。

```shell-session
$ sudo systemctl restart rsyslog
$ psql -U postgres -d postgres -c "SELECT 1"
 ?column?
----------
        1
(1 行)

$ psql -U postgres -d template1 -c "SELECT 1"
 ?column?
----------
        1
(1 行)

$ sudo tail /var/log/postgresql/main.log
(省略)
Dec 20 11:11:51 node-1 postgres[5487]: [unknown]@[unknown] LOG:  connection received: host=[local]
Dec 20 11:11:58 node-1 postgres[5489]: [unknown]@[unknown] LOG:  connection received: host=[local]
$ sudo tail /var/log/postgresql/postgres.log
Dec 20 11:11:51 node-1 postgres[5487]: postgres@postgres LOG:  connection authenticated: user="postgres" method=trust (/var/lib/pgsql/17/data/pg_hba.conf:117)
Dec 20 11:11:51 node-1 postgres[5487]: postgres@postgres LOG:  connection authorized: user=postgres database=postgres application_name=psql
Dec 20 11:11:51 node-1 postgres[5487]: postgres@postgres LOG:  statement: SELECT 1
Dec 20 11:11:51 node-1 postgres[5487]: postgres@postgres LOG:  disconnection: session time: 0:00:00.003 user=postgres database=postgres host=[local]
$ sudo tail /var/log/postgresql/template1.log
Dec 20 11:11:58 node-1 postgres[5489]: postgres@template1 LOG:  connection authenticated: user="postgres" method=trust (/var/lib/pgsql/17/data/pg_hba.conf:117)
Dec 20 11:11:58 node-1 postgres[5489]: postgres@template1 LOG:  connection authorized: user=postgres database=template1 application_name=psql
Dec 20 11:11:58 node-1 postgres[5489]: postgres@template1 LOG:  statement: SELECT 1
Dec 20 11:11:58 node-1 postgres[5489]: postgres@template1 LOG:  disconnection: session time: 0:00:00.004 user=postgres database=template1 host=[local]
```

これでデータベースごとにログファイルを分ける設定は完了です。

## おわりに

この記事では rsyslog で PostgreSQL のログを別ファイルに分ける方法を紹介しました。rsyslog の設定を行う際は `rsyslogd -N 1` コマンドで構文をチェックしてくれるので、思ったようにログが出力されない場合は実行してみるとよいです。

```shell-session
$ rsyslogd -N 1
rsyslogd: version 8.2310.0-4.el9, config validation run (level 1), master config /etc/rsyslog.conf
rsyslogd: error during parsing file /etc/rsyslog.d/postgresql.conf, on or before line 4: syntax error on token 'action' [v8.2310.0-4.el9 try https://www.rsyslog.com/e/2207 ]
rsyslogd: could not interpret master config file '/etc/rsyslog.conf'. [v8.2310.0-4.el9 try https://www.rsyslog.com/e/2207 ]
```

また、1 つのファイルにログを出力し続けると、ファイルが大きくなりすぎてしまうので、定期的にファイルを切り替えるように設定したほうがよいです。logrotate の rsyslog 向けの設定ファイルにエントリを追加するのが簡単です。

```config:/etc/logrotate.d/rsyslog
/var/log/cron
/var/log/maillog
/var/log/messages
/var/log/secure
/var/log/spooler
/var/log/postgresql/*.log
{
    missingok
    sharedscripts
    postrotate
        /usr/bin/systemctl -s HUP kill rsyslog.service >/dev/null 2>&1 || true
    endscript
}
```

最後に、PostgreSQL のログを rsyslog で取る場合、動的リンカや `archive_command` パラメータに指定したコマンドのエラーメッセージなど、一部のログが取れないことや、rsyslog であまり凝った設定を行うと、その分、ログ出力の負荷が増えることに注意してください。