俺様サーバー構築記 - systemd-journald

「俺様サーバー構築記 - 基本方針」以来構築を続けてきた俺様パソコン環境ですが、サーバーマシンも基本的なインストールが出来て、ぼちぼち色んなサービスなどを構築する段階になってきました。

そして自動化やらデーモンやらを模索するとなれば、問題になるのはログです。

という訳で systemd におけるログ保存システム systemd-journald 及びその周辺を調べました。ひとまず今後しばらく私が使う予定の範囲の概観のみです。

余談ですけどやっぱり私は systemd が嫌いです。 journald 関係を調べて確信しました。私の美意識に合いません。

関係するコマンドやサービス

下記のコマンドやサービスがあるようです。

systemd-journald

systemd においてログを収集し保存するサービスの本体… と言えば良いんでしょうか。

journalctl

journald はログをバイナリファイルに保存するらしく、それを人の目で読める形（つまりテキスト）にしたり、ついでに絞り込んだりします。

どうして grep とか RDB とかではダメだったのでしょうねぇ

systemd-cat

ユーザが実行する通常のコマンドの出力をジャーナルに記録する為のコマンドです。

systemd-journal-gatewayd

ネットワーク越しにジャーナルイベントを提供するそうです。そしてクライアントは HTTP でつなげなさい、と。

HTTP を使いたい気持ちもわからんではないのですがね、違うプロトコルは選択させてもらえない模様。こういう押し付けがましい所が本当に気に入らない。ぐぐっても日本語情報がまだ無いようなので、素直に man systemd-journal-gatewayd で頑張って英語を読むのが良さそう。

systemd-journal-remote

systemd-journal-upload

systemd ジャーナルはローカルに保存されますが、それを別のマシンに転送する為のコマンドです。同じ名前でサービスも用意されている模様。

これも HTTP のみ。厳密に言うと remote で pull 型のログ収集を試みる際には転送プロトコルに工夫の余地あり。知らんけど（もうやる気無し）

関係するディレクトリとその設定

一般論としては、 systemd-journald はそのログを /run/log/journal ディレクトリの中に保存する模様。但しここは揮発性のディレクトリであってマシン再起動時に消えてしまうので、残したいなら /var/log/journal ディレクトリを作成しておけば、そこに記録される。その辺の切り替えは /etc/systemd/journald.conf の [Journal] Storage の値で切り替えるようになっていて、通常はここが auto なのでこのような自動切り替え動作になるようです。

$ grep -e "^\[" -e Storage /etc/systemd/journald.conf
[Journal]
#Storage=auto

…どうしてディレクトリパスの指定じゃないんでしょうね。こういう、選択肢を与えない束縛が本当に気に入らないのです。何と言うか、こう、悪名高い Microsoft のやり口に良く似ているような気がするんですが、何か関係あるんでしょうか？

それはそれとして。ArchLinux に限って言えば、 /var/log/journal ディレクトリは事前に用意されています。そして /run/log/journal は存在しません。

$ ls -ld /run/log/journal /var/log/journal
ls: '/run/log/journal' にアクセスできません: そのようなファイルやディレクトリはありません
drwxr-sr-x 4 root systemd-journal 4  4月 29 17:28 /var/log/journal

これは ArchLinux の仕様のようですな。

参考文献：systemd/ジャーナル - ArchWiki

Arch Linux では /var/log/journal/ ディレクトリは systemd の一部であり、あなたや何らかのプログラムがディレクトリを削除した場合、systemd は自動で再作成しませんが、systemd のアップデートがあるとディレクトリは作りなおされます。それまでログは代わりに /run/systemd/journal に書き込まれます。ただし再起動時にこのログは消失してしまいます。

更に zfs 限定の要件になるようですが、この /var/log/journal はアクセス制御リスト (acl) が有効でなければならないらしい。

参考文献：9.9 起動時に systemd-tmpfiles-setup.service の実行に失敗する - 9 トラブルシューティング - systemd - ArchWiki

こういう systemd の押し付けが（以下略）

私のマシンはすべて、ルート / 以下全部丸ごと zfs になっていて、zfs ではデフォルトで acl は無効になっています。これを有効にしなければなりません。
同時に xattr も設定する事が推奨されている由。

参考文献：4.4 root ファイルシステムの設定 - 4 ZFS ファイルシステムのセットアップ - ZFS に Arch Linux をインストール - ArchWiki

$ zfs get xattr tank/main
NAME       PROPERTY  VALUE  SOURCE
tank/main  xattr     on     default
$ zfs get acltype tank/main
NAME       PROPERTY  VALUE     SOURCE
tank/main  acltype   off       default

root ユーザになって設定します。

$ su
パスワード:
# zfs set xattr=sa tank/main
# zfs set acltype=posixacl tank/main
# exit
exit

ちなみに、この期に及んでも未だ sudo コマンドをインストールしないのは、私の拘りです。 sudo コマンドはセキュリティリスクが高いので基本的に使わない方が良い、という意見を私は支持しています。

systemd-journald の注意点

こんな情報がありました。弩阿呆！

参考文献：9.5 短いプロセスがログを出力しない - 9 トラブルシューティング - systemd - ArchWiki

短いプロセスがログを出力しない

journalctl -u foounit.service が短いプロセスについてなにも表示しない場合、かわりに PID を見て下さい。例えば、systemd-modules-load.service が失敗したとき、systemctl status systemd-modules-load によってそれが PID 123 として動いているとわかったら、その PID の journal の出力を見ることができます、journalctl -b _PID=123。journal の _SYSTEMD_UNIT や _COMM などのメタデータは非同期に収集され /proc ディレクトリにプロセスが存在している時だけ表示されます。これを修正するには、SCM_CREDENTIALS のように、ソケット接続を使ってデータを流すようカーネルを変更する必要があります。

参考文献：9.8 少しづつ起動時間が長くなっている - 9 トラブルシューティング - systemd - ArchWiki

少しづつ起動時間が長くなっている

systemd-analyze を使用して、以前と比べて起動時間が明らかに伸びていると複数のユーザーが報告しています。systemd-analyze blame を使って NetworkManager が起動するのに異常に長い時間かかるようになったという報告もあります。

問題の原因として /var/log/journal が巨大になりすぎている可能性があります。そのような場合、フォルダ内のファイルを全て削除して journal のファイルサイズをここに書かれているように制限するよう設定すれば解決します（できればファイルを削除する前に、どこかに一時的にバックアップしてください）。

文字コードを euc にしている場合

今時こんなのは私だけだと思いますけども。 journalctl というよりも、その中で呼び出している less の問題です。文字化けします。

良い子の皆さんは utf-8 にしましょう、そうすればこんな問題は発生しません。

$ journalctl
Hint: You are currently not seeing messages from other users and the system.
      Users in groups 'adm', 'systemd-journal', 'wheel' can see all messages.
      Pass -q to turn off this notice.
-- Logs begin at Sun 2019-07-21 23:17:33 JST, end at Sat 2019-08-03 18:18:16 JST. --
 7<B7><EE> 21 23:17:33 client0 systemd[1336]: Reached target Paths.
 7<B7><EE> 21 23:17:33 client0 systemd[1336]: Listening on GnuPG cryptographic agent and passphrase cache (restricted).
 7<B7><EE> 21 23:17:33 client0 systemd[1336]: Starting D-Bus User Message Bus Socket.
 7<B7><EE> 21 23:17:33 client0 systemd[1336]: Reached target Timers.
 7<B7><EE> 21 23:17:33 client0 systemd[1336]: Listening on GnuPG cryptographic agent and passphrase cache.
 7<B7><EE> 21 23:17:33 client0 systemd[1336]: Listening on Multimedia System.
 7<B7><EE> 21 23:17:33 client0 systemd[1336]: Listening on GnuPG cryptographic agent and passphrase cache (access for web browsers).
 7<B7><EE> 21 23:17:33 client0 systemd[1336]: Listening on p11-kit server.
 7<B7><EE> 21 23:17:33 client0 systemd[1336]: Listening on GnuPG network certificate management daemon.
 7<B7><EE> 21 23:17:33 client0 systemd[1336]: Listening on GnuPG cryptographic agent (ssh-agent emulation).
 7<B7><EE> 21 23:17:33 client0 systemd[1336]: Listening on D-Bus User Message Bus Socket.
 7<B7><EE> 21 23:17:33 client0 systemd[1336]: Reached target Sockets.

これは環境変数 LESSCHARSET を指定する事で解消します。

$ export LESSCHARSET=dos
$ journalctl
Hint: You are currently not seeing messages from other users and the system.
      Users in groups 'adm', 'systemd-journal', 'wheel' can see all messages.
      Pass -q to turn off this notice.
-- Logs begin at Sun 2019-07-21 23:17:33 JST, end at Sat 2019-08-03 18:18:16 JST. --
 7月 21 23:17:33 client0 systemd[1336]: Reached target Paths.
 7月 21 23:17:33 client0 systemd[1336]: Listening on GnuPG cryptographic agent and passphrase cache (restricted).
 7月 21 23:17:33 client0 systemd[1336]: Starting D-Bus User Message Bus Socket.
 7月 21 23:17:33 client0 systemd[1336]: Reached target Timers.
 7月 21 23:17:33 client0 systemd[1336]: Listening on GnuPG cryptographic agent and passphrase cache.
 7月 21 23:17:33 client0 systemd[1336]: Listening on Multimedia System.
 7月 21 23:17:33 client0 systemd[1336]: Listening on GnuPG cryptographic agent and passphrase cache (access for web browsers).
 7月 21 23:17:33 client0 systemd[1336]: Listening on p11-kit server.
 7月 21 23:17:33 client0 systemd[1336]: Listening on GnuPG network certificate management daemon.
 7月 21 23:17:33 client0 systemd[1336]: Listening on GnuPG cryptographic agent (ssh-agent emulation).
 7月 21 23:17:33 client0 systemd[1336]: Listening on D-Bus User Message Bus Socket.
 7月 21 23:17:33 client0 systemd[1336]: Reached target Sockets.

LESSCHARSET=dos というのは、本当は Shift_JIS への対応なんですけども。基本的には EUC でもほぼ同じ制御になる為、 EUC でも有効な対策です。

実験: systemd-cat

一般ユーザで systemd-cat コマンドを使用してみます。

$ systemd-cat ls -la /

結果を確認する為 journalctl コマンドで表示したのですが、なんと！バイナリ扱いになっていました。漢字混じりだったせいでしょうか？

$ journalctl -e | tail -n21
Hint: You are currently not seeing messages from other users and the system.
      Users in groups 'adm', 'systemd-journal', 'wheel' can see all messages.
      Pass -q to turn off this notice.
 8月 03 18:22:28 client0 ls[2315]: [7B blob data]
 8月 03 18:22:28 client0 ls[2315]: [45B blob data]
 8月 03 18:22:28 client0 ls[2315]: [46B blob data]
 8月 03 18:22:28 client0 ls[2315]: [58B blob data]
 8月 03 18:22:28 client0 ls[2315]: [48B blob data]
 8月 03 18:22:28 client0 ls[2315]: [47B blob data]
 8月 03 18:22:28 client0 ls[2315]: [47B blob data]
 8月 03 18:22:28 client0 ls[2315]: [48B blob data]
 8月 03 18:22:28 client0 ls[2315]: [58B blob data]
 8月 03 18:22:28 client0 ls[2315]: [60B blob data]
 8月 03 18:22:28 client0 ls[2315]: [47B blob data]
 8月 03 18:22:28 client0 ls[2315]: [47B blob data]
 8月 03 18:22:28 client0 ls[2315]: [48B blob data]
 8月 03 18:22:28 client0 ls[2315]: [48B blob data]
 8月 03 18:22:28 client0 ls[2315]: [47B blob data]
 8月 03 18:22:28 client0 ls[2315]: [59B blob data]
 8月 03 18:22:28 client0 ls[2315]: [47B blob data]
 8月 03 18:22:28 client0 ls[2315]: [47B blob data]
 8月 03 18:22:28 client0 ls[2315]: [47B blob data]
 8月 03 18:22:28 client0 ls[2315]: [47B blob data]
 8月 03 18:22:28 client0 ls[2315]: [47B blob data]

とにかく全部出力するオプション -a を指定すれば出力されます。

$ journalctl -ae | tail -n21
Hint: You are currently not seeing messages from other users and the system.
      Users in groups 'adm', 'systemd-journal', 'wheel' can see all messages.
      Pass -q to turn off this notice.
 8月 03 18:22:28 client0 ls[2315]: 合計 19
 8月 03 18:22:28 client0 ls[2315]: drwxr-xr-x  16 root root   20  7月  5 20:21 .
 8月 03 18:22:28 client0 ls[2315]: drwxr-xr-x  16 root root   20  7月  5 20:21 ..
 8月 03 18:22:28 client0 ls[2315]: lrwxrwxrwx   1 root root    7  5月 23 23:18 bin -> usr/bin
 8月 03 18:22:28 client0 ls[2315]: drwxr-xr-x   2 root root    6  7月 22 23:00 boot
 8月 03 18:22:28 client0 ls[2315]: drwxr-xr-x  19 root root 3360  8月  3 18:17 dev
 8月 03 18:22:28 client0 ls[2315]: drwxr-xr-x  61 root root  133  7月 27 22:55 etc
 8月 03 18:22:28 client0 ls[2315]: drwxr-xr-x   4 root root    4  7月 20 23:58 home
 8月 03 18:22:28 client0 ls[2315]: lrwxrwxrwx   1 root root    7  5月 23 23:18 lib -> usr/lib
 8月 03 18:22:28 client0 ls[2315]: lrwxrwxrwx   1 root root    7  5月 23 23:18 lib64 -> usr/lib
 8月 03 18:22:28 client0 ls[2315]: drwxr-xr-x   2 root root    2 12月  6  2018 mnt
 8月 03 18:22:28 client0 ls[2315]: drwxr-xr-x   2 root root    2 12月  6  2018 opt
 8月 03 18:22:28 client0 ls[2315]: dr-xr-xr-x 217 root root    0  8月  3 18:17 proc
 8月 03 18:22:28 client0 ls[2315]: drwxr-x---   4 root root    6  7月 22 00:11 root
 8月 03 18:22:28 client0 ls[2315]: drwxr-xr-x  17 root root  460  8月  3 18:17 run
 8月 03 18:22:28 client0 ls[2315]: lrwxrwxrwx   1 root root    7  5月 23 23:18 sbin -> usr/bin
 8月 03 18:22:28 client0 ls[2315]: drwxr-xr-x   4 root root    4  4月 29 16:39 srv
 8月 03 18:22:28 client0 ls[2315]: dr-xr-xr-x  13 root root    0  8月  3 18:17 sys
 8月 03 18:22:28 client0 ls[2315]: drwxrwxrwt  13 root root  320  8月  3 18:18 tmp
 8月 03 18:22:28 client0 ls[2315]: drwxr-xr-x   9 root root   11  7月 22 23:30 usr
 8月 03 18:22:28 client0 ls[2315]: drwxr-xr-x  12 root root   16  7月 27 22:55 var

色々なオプションについては個別に調べて下さい。

終わりに

今回は大量に愚痴が出てしまいました。読み辛い箇所についてはお詫びします。が、反省も後悔もしていません。うが〜！

ともあれ様々な自動化の際に必要となるログ出力の目処は立ちました。やったね