Journald | ||
---|---|---|
HOME |
RHEL/CentOS 7 から (...と言わず他の多数のディストリビューションも)、伝統的な init が systemd に取って代わられ、自ずと SYSLOG は systemd スィートの一部である journal というものに替わってしまった。しばらくは「RHEL7糞食らえ」と遠ざけていたのだが、遂に触らざるをえない機会が訪れ、そうもいかなくなった。こうなったら毒を食らわば皿まで。使い切ってやろうではないか。
少なくともこれだけはやっておきたい。RHEL/CentOS 7 のデフォルトでは、ジャーナルは /run/log/journal に書き込まれるが、これはメモリ上の揮発性のログであり、リブートすれば消えてしまう。そもそも /run/ は tmpfs つまりRAMディスクである。journald.conf の既定値は Storage=auto であり、/var/log/journal/ ディレクトリを作ってやれば次回の systemd-journald の起動からジャーナルは揮発性でないファイル実体としてそこで管理される。Storage=persistent にしておくと、/var/log/journal/ が存在しなかった場合には自動的にディレクトリが作成される。
RHEL/CentOS 7 の既定値では、journald は SYSLOGソケット /run/systemd/journal/syslog へもログを転送するにようになっている。そして rsyslog 側では、imjournal インプットモジュールを利用して journalプロトコルによってジャーナルデータベースファイルそのものを直接ポーリングしつつ、imuxsock インプットモジュールで前記の journal/syslog ソケットを開いておきながらなお且つ "$OmitLocalLogging on" でソケットを無視するというどっちつかずな設定になっている。"$OmitLocalLogging on" になっているのは、そうしないとジャーナルからの直接読み取りとソケット転送とでほとんど全てのログエントリがダブって記録されてしまうからだ。
永続ストレージが有効化してあれば、journald 自体がテキストログファイルより容量効率の良いバイナリデータでログを保存しており、同様な内容のものを rsyslog でテキストログにも保存するのは無駄である。また、imjournal によるジャーナルデータベースのポーリングというのは負荷が高く低速な処理であり、rsyslog 開発者は、特に理由のない限り imjournal の使用を推奨していない。ジャーナル特有のリッチな構造化ログデータを受け取るには journal/syslog ソケット経由では無理で imjournal モジュールが必要だが、構造化データを SYSLOG で利用する機会は希で、もし従来型のテキストログにも保存したいとしても、imuxsock 経由つまり journald からの SYSLOGソケット転送で充分だということだ。
また、もしログファイルを従来のようにファシリティやデーモン毎に分けたいというだけの理由で rsyslog でも書き出したいというのなら、ナンセンスだと私は思う。必要なログを絞り込んで閲覧する機能を journalctl は充分に備えている。あとは journalctl コマンドへの慣れの問題だけだ。
そんなわけで、ログはほぼ全て journald に管理させ、rsyslog は、rsyslog自体のログやTCPやUDP経由でのリモートロギングを受け取りたい場合を除いて何もさせない方針で行くのがよいと今現在は思っている。
以下の箇所を修正・確認後 `systemctl restart systemd-journald.service' で journald をリスタートする。
以下の箇所を修正・確認後 `systemctl restart rsyslog.service' で rsyslog をリスタートする。rsyslog 7 についてはこちらでみっちりと検証している。
systemd-cat [-t SYSLOG_IDENTIFIER] [-p PRIORITY] [COMMAND [ARGS..]]
例えば、
systemd-cat -t journaltest -p info uptime
-t オプションの引数はジャーナルレコードの "prog[PID]:" といったフィールド (レガシーSYSLOGで言うところのTAGフィールド) の prog 部分にする文字列。-p オプションで指定するのは SYSLOGプライオリティ(シビアリティ)で、文字表記でも数字表記でも可 (後述 journalctlコマンド解説のフィルタオプション参照)。そして `COMMAND + 引数` の STDOUT と STDERR の両方がジャーナルに送られる。また、パイプでメッセージを渡すことも可能で、
vmstat -S M 2>&1 |systemd-cat -t journaltest
RHEL/CentOS 7 の rsyslog.conf や rsyslog.d/ 配下のインクルードファイルは下位互換性を重視して古いフォーマットで書かれているが、Rsyslogの推奨する通り可能な限り rsyslog ver.7以降の新フォーマットを使うように全面的に書き直すと以下のようになる。module(load="imjournal") の行は、新書式での記述法を示すため参考として載せた。
rsyslog.conf (新書式)
module(load="imuxsock" SysSock.Use="off" SysSock.Name="/run/systemd/journal/syslog")
#module(load="imjournal" StateFile="/var/lib/rsyslog/imjournal.state")
#### GLOBAL DIRECTIVES ####
$WorkDirectory /var/lib/rsyslog
$ActionFileDefaultTemplate RSYSLOG_TraditionalFileFormat
$IncludeConfig /etc/rsyslog.d/*.conf
#### RULES ####
# Log all kernel messages to the console.
# Logging much else clutters up the screen.
#kern.* /dev/console
<-ローカルロギングルールが続く. 中略->
local7.* /var/log/boot.log
rsyslog.d/listen.conf (メイン設定ファイルに新書式のオプションとして指定するので全てコメントアウト)
#$SystemLogSocketName /run/systemd/journal/syslog
上記変更により /var/log 配下の大多数のテキストログが更新されなくなるので、空のログファイルを無駄にログローテートしないよう、notifempty 行を加えておくのがよい。logrotate についてはこちらで解説している。
ジャーナル=>rsyslog=>テキストログ の逆に、レガシーSYSLOGプロトコル=>rsyslog=>ジャーナル という処理もできる。rsyslog の omjournal アウトプットモジュールを使う。リモートロギング全般に関して詳しくは rsyslog(v7) のページを参照のこと。ただし、素直に omjounal を使うと、リモートから受け取ったログエントリのホスト名が、リモートでなく SYSLOGサーバのホスト名になってしまって区別ができず実用に堪えない(※)。善後策は見つけたが、それを示す前に、まずは素のやり方を示そう。
※ CentOS 7.2 の rsyslog-7.4.7 での検証。ログフォーマットTemplate を使ってリモートホスト名をメッセージに追加することも模索してみたが、今のところ、omjournal ではメッセージTemplate が使えないようだ。GitHubを覗いてみたところ、最先端の rsyslog ver.8系にはパッチが既にマージされている。
rsyslog.conf
module(load="imuxsock" SysSock.Use="off" SysSock.Name="/run/systemd/journal/syslog") module(load="imudp") module(load="omjournal") #### GLOBAL DIRECTIVES #### $WorkDirectory /var/lib/rsyslog $ActionFileDefaultTemplate RSYSLOG_TraditionalFileFormat $IncludeConfig /etc/rsyslog.d/*.conf #### RULES #### # Log all kernel messages to the console. # Logging much else clutters up the screen. #kern.* /dev/console <-ローカルロギングルールが続く. 中略-> local7.* /var/log/boot.log ruleset(name="RemoteUDP" queue.type="FixedArray" ) { $IncludeConfig /etc/rsyslog.d/remote-udp.conf_r } input(type="imudp" port="514" ruleset="RemoteUDP")
rsyslog.d/listen.conf (全てコメントアウト)
#$SystemLogSocketName /run/systemd/journal/syslog
rsyslog.d/remote-udp.conf_r (UDPログ送信元マシンのIPが192.168.1.24と仮定)
$AllowedSender UDP, 192.168.1.24/32 if $fromhost-ip == '192.168.1.24' then { action(type="omjournal") stop }
ジャーナルに注ぎ込まれたエントリはこんな具合になる (centos7u は当のジャーナルのあるローカルサーバ):
8月 04 23:25:55 centos7u ntpd[2485]:[4715]: Listen normally on 2 eth0 192.168.1.24 UDP 123 8月 04 23:25:55 centos7u ntpd[2485]:[4715]: peers refreshed 8月 04 23:25:55 centos7u ntpd[2485]:[4715]: 0.0.0.0 c012 02 freq_set kernel -0.139 PPM
これでは、[PID]: が二重になっていること以外、ローカル発のログなのかリモートからのログなのか区別する手掛かりがなく、どのマシンから送られてきたのかに至っては全く分からない。
そこで、一捻り加えて、rsyslog の omprog アウトプットモジュールを活用する。メッセージが来る毎に、systemd-cat を実行することによって Journal API でジャーナルへ注ぎ込むという寸法だ。omprog ならメッセージフォーマットテンプレートが使える。rsyslog ver.7 の omjournal にも Template パッチが当たるか RHEL/CentOS 7 で rsyslog8 パッケージが選択できるようになるまでの一時凌ぎには充分だろう。
omprog のやっていることは rsyslog のレガシー書式での "local3 ^/path/to/prog" といったログ振り分けルールと表面上は一緒だ。しかし、ドキュメントによると、内部処理は別もので、旧式の "^" ルールは大量のログエントリを扱うのには向いていないという旨のことが書かれている。やるなら必ず、下記のように新しいスタイルで書くことをお勧めする。
rsyslog.conf
module(load="imuxsock" SysSock.Use="off" SysSock.Name="/run/systemd/journal/syslog") module(load="imudp") module(load="omprog") <-omjournalでなくomprogモジュールをロード #### GLOBAL DIRECTIVES #### $WorkDirectory /var/lib/rsyslog $ActionFileDefaultTemplate RSYSLOG_TraditionalFileFormat $IncludeConfig /etc/rsyslog.d/*.conf #### RULES #### # Log all kernel messages to the console. # Logging much else clutters up the screen. #kern.* /dev/console <-ローカルロギングルールが続く. 中略-> local7.* /var/log/boot.log template(name="RemoteToJnlTpl" type="string" string="%HOSTNAME%: %syslogtag:F,58:1%%msg:::sp-if-no-1st-sp%%msg:::drop-last-lf%\n") ruleset(name="RemoteUDP" queue.type="FixedArray" ) { $IncludeConfig /etc/rsyslog.d/remote-udp.conf_r } input(type="imudp" port="514" ruleset="RemoteUDP")
メッセージ用 template は、rsyslog の現在のところのデフォルトフォーマットである RSYSLOG_TraditionalFileFormat
"%TIMESTAMP% %HOSTNAME% %syslogtag%%msg:::sp-if-no-1st-sp%%msg:::drop-last-lf%\n"
を元に、%TIMESTAMP% を取り除き (受け取り側で付くので送り側での発生時刻は邪魔)、%HOSTNAME% の後ろにコロンを付け、%syslogtag% の最後のコロンを取り除くため rsyslog の プロパティリプレーサー機能 によりコロン(16進文字コード"3A"-> 10進に変換して"58") をデリミタとして分解した第1フィールドだけにする、という味付けをしてみた。
rsyslog.d/remote-udp.conf_r (UDPログ送信元マシンのIPが192.168.1.24と仮定)
$AllowedSender UDP, 192.168.1.24/32 if $fromhost-ip == '192.168.1.24' then { action(type="omprog" binary="/bin/systemd-cat" template="RemoteToJnlTpl") stop }
omprog はログメッセージを、指定されたテンプレートに従って整形した後、指定のプログラムの標準入力に流し込み、メッセージの終わりでプログラムに EOF を送る。まさに systemd-cat に打ってつけだ。 binary= 属性は、rsyslog ver.7 で試した限り、実行ファイルパスだけしか受け付けなかった。Rsyslog のドキュメント(Ver.8の方が分かりやすい) で使用例として示されているように binary="/bin/systemd-cat --identifier=centos6u" とオプションまで指定してしまうと機能してくれなかった。
ジャーナルに注ぎ込まれたエントリはこうなった (centos6u はリモートマシン):
8月 04 23:30:20 centos7u cat[7416]: centos6u: ntpd[2731] Listen normally on 2 eth0 192.168.1.24 UDP 123 8月 04 23:30:20 centos7u cat[7416]: centos6u: ntpd[2731] peers refreshed 8月 04 23:30:20 centos7u cat[7416]: centos6u: ntpd[2731] 0.0.0.0 c012 02 freq_set kernel -0.139 PPM
これならしっかり区別がつく。これらのログエントリを journalctl で選り出して読むには、これまた少し工夫が要る (journalctl のフィルタについては後述)。アイデンティファイアが cat となっているのは、どうやら systemd-cat が中間処理的に /bin/cat および /usr/bin/cat を呼んでいるためらしい。そこで、下記のようにやれば当該のレコードがフィルタリングできる。
journalctl /bin/cat --no-pager |grep centos6u:
いや、しかしやはり、IDENTIFIER が "cat" では納得がいかない。omprog アクションの binary 属性が引数を採れないなら、ラッパーシェルスクリプトを噛ませてやれ、というわけで、以下のような改善策を思いついた。まず、このようなラッパーを作る。
#!/bin/sh MYNAME=$(basename $0) exec /bin/systemd-cat -t ${MYNAME#*-}
これを例えば /usr/local/bin/ に remote2jour として実行ビットを立てて置き、systemd-cat の -t オプション引数にしたい文字列をハイフォンでつないだ名前でシンボリックリンクを作る。アイデンティファイアを "omprog" にしたいとすれば:
# cd /usr/local/bin # ln -s remote2jour remote2jour-omprog
そして、remote-udp.conf_r をこう書き換える。
$AllowedSender UDP, 192.168.1.24/32
if $fromhost-ip == '192.168.1.24' then {
action(type="omprog"
binary="/usr/local/bin/remote2jour-omprog"
template="RemoteToJnlTpl")
stop
}
ジャーナルにはこのように記録されるようになった。
8月 04 23:40:35 centos7u omprog[7416]: centos6u: ntpd[2132] Listen normally on 2 eth0 192.168.1.24 UDP 123 8月 04 23:40:35 centos7u omprog[7416]: centos6u: ntpd[2132] peers refreshed 8月 04 23:40:35 centos7u omprog[7416]: centos6u: ntpd[2132] 0.0.0.0 c012 02 freq_set kernel -0.153 PPM
ログを選り分けるには、今度はこうやる。識別名が "omprog" のログなど自然には現れないはずなので、リモートログをより確実に選び出すことができる。目出度しめでたし。
journalctl SYSLOG_IDENTIFIER=omprog --no-pager |grep centos6u:
rootアカウントなら全てのジャーナルを読めるのは当たり前だが、一般ユーザを adm グループまたは systemd-journal グループに加えるとそのユーザは全てのジャーナルを読むことができる。
# usermod hoge -a -G adm
"journalctl" は長くていちいち打ちづらい。alias を設定しておくとよい。~/.bashrc でエイリアスを設定。
alias jour='journalctl'
設定したら、シェルセッションに入り直し、`type jour' あるいは `which jour' で確認。
とりあえず使いこなしたいものだけ、実際に叩いてみながら挙げてみた。もちろん適宜組み合わせて使う。
旧来のファイルログで言えば `tail -n N /var/log/logfile'。最後のN 行だけを表示する。 -n の引数を省いた時のデフォルトは 10、つまり -n 10 と同義。
旧来のファイルログで言えば `tailf /var/log/logfile'。追加されるエントリをリアルタイムに追加表示していく。-f を使うと暗黙的に -n (10)も宣言される。コマンドした後からの新エントリだけしか表示したくなければ `-f -n 0' と指定すればよい。逆に、以前のエントリも全部表示した上で追跡を始めたい場合は `-f --no-tail'。表示をやめるには Ctrl-C。
長いオプションでは --pager-end つまり、カーソルを自動的に最終行にフォーカスする。バッファを食い潰さないよう暗黙的に '-n 1000' も宣言される。
つまり --reverse。古いエントリが最後、最新のエントリが最上段になるよう逆順で表示する。-e と併用すると、最上行にフォーカスされるかと思いきや、最下行つまり一番古いエントリにフォーカスされてあまり意味がない。
ジャーナルメッセージカタログからの説明テキストも付加して表示する。時としてデバグの役に立つ。
表示形式の選択。他に幾つもあるが、今のところ使い道の分からないものは省く。
言わずもがな、タイムスタンプをUTCに。
上でも既に書いたが、旧来のファイルログで言えば `tail -n N /var/log/logfile'。-n の引数を省いた時のデフォルトは 10、つまり -n 10 と同義。
どのシステムブート・ライフのエントリを表示するか。`-b 0' `-b -0' もしくは `-b' だけで引数を省くと今回のブートライフ中のメッセージ。`-b -1' は前回のブートライフ中のメッセージ。`journalctl --list-boots' でブートID (32文字) を調べておき、'-b xxxxxxxxxxx' という具合にブートIDで指定することもできるし、それを起点として2回前のブートライフなら '-b xxxxxxxxxxx-2' という指定もできる。
長いオプションだと --dmesg。つまり、旧来テキストログの ` dmesg' あるいは ` less /var/log/dmesg' と同義。
マッチする Systemdユニットに関するエントリを表示する。例えば `journalctl -u ntpd'。
ひとつの journalctl クエリの中で同じフィールド名を複数回使うと、それらは OR で評価される。`journalctl _SYSTEMD_UNIT=ntpd.service _SYSTEMD_UNIT=sshd.service' といった場合だ。別のフィールド名が併用されていると、それらは AND で評価される。`journalctl _SYSTEMD_UNIT=ntpd.service _PID=678' といった時だ。
-u オプションの引数はユニット名ではなくユニット名グロブパターンであり、裏では、journal フィールドマッチに変換されている。例えば `-u ntpd' というフィルタをコマンドすると、journalctl は Systemd に問い合わせて "ntpd" を名前に持つユニット (.serviceや .socket などのユニットタイプ一切合切) があるかどうか探し、得られた完全ユニット名 (.service や.socket付き) を使って Journalフィールドマッチ "_SYSTEMD_UNIT=ntpd.service + UNIT=ntpd.service" を発行していると見られる。_SYSTEMD_UNIT= やUNIT= フィールドマッチの引数は必ず完全ユニット名でなければならないのに対して、-u オプションの引数文字列は完全ユニット名でもベースネームやそのグロブパターンでもいい。-u の引数がドットを含んでいない時は、ユニットのベースネームとの一致を探していると見なすようで、`-u ntpd' は ntpdate.service にはマッチしない。グロブパターンはシェルグロブ相当で、`-u ntp?' や `-u ntp[a-z]' はユニット名 ntpd.service (や、もし仮に存在すればntpd.socketにも) にヒットするし、`-u ntp*' は加えて ntpdate.service などにもマッチする。最後の例によって発行されている実際のフィールドマッチは "_SYSTEMD_UNIT=ntpd.service + UNIT=ntpd.service + _SYSTEMD_UNIT=ntpdate.service + UNIT=ntpdate.service" だと考えると、検証で得られた各種出力内容の辻褄が合う。
SYSLOGプライオリティ(つまりシビアリティ/SYSLOGレベル/重篤度)によるフィルタ。数値表記と文字表記のどちらでも指定可能。
数値表記 | 文字表記 |
0 | emerg |
1 | alert |
2 | crit |
3 | err |
4 | warning |
5 | notice |
6 | info |
7 | debug |
一般的なログハンドリング規則と同様、`-p warning' を指定した場合は SYSLOGレベル 4 以上 (4~0) のエントリが表示される。warning レベルのみ、あるいは warning から crit までだけに絞り込みたい時は、`-p 4..4' や `-p 4..2' といった指定方法がある。-p オプションは裏では、PRIORITY=PriorityNum というJournalフィールドフィルタに変換されている。-p が引数に文字表記も採れるのに対して、PRIORITY= は数値表記しか受け付けない。-p が通約してくれているとも言える。
Journalフィールド系フィルタのひとつ。認証系のログを見たい時、旧来のテキストログだと `less /var/log/secure' とやるところだが、journalctl で同義のことをやるには `journalctl SYSLOG_FACILITY=10' となる。文字列(キーワード)での指定は受け付けてもらえない。
数値 | キーワード | 数値 | キーワード | 数値 | キーワード |
0 | kern | 8 | uucp | 16 | local0 |
1 | user | 9 | - | 17 | local1 |
2 | 10 | authpriv | 18 | local2 | |
3 | daemon | 11 | ftp | 19 | local3 |
4 | auth | 12 | - | 20 | local4 |
5 | syslog | 13 | - | 21 | local5 |
6 | lpr | 14 | - | 22 | local6 |
7 | news | 15 | cron | 23 | local7 |
ログエントリを生成した実行プログラムを基準にログを絞り込む。例えば、
# journalctl /usr/sbin/ntpd
journalctl はまず /usr/sbin/ntpd が実行プログラムとしてファイルシステム上に存在するかどうか確認してから、カノニカライズつまり "ntpd" というファイル名だけにして、Journalフィールドクエリ `_EXE=ntpd + _COMM=ntpd + _CMDLINE=ntpd' を発行していると見られる。例えば /usr/bin/vncserver のように Systemdユニットの ExecStart が perl によるラッパースクリプトである場合、Journalフィールド _EXE の値は `/usr/bin/perl' になってしまっているが、これならヒットするというわけだ。
全く同じ書式でも、引数のパスがデバイスファイルだった場合は、`_KERNEL_DEVICE=Value ' Journalフィールドマッチが行われる。
Journalフィールドフィルタのひとつ。プロセスのPIDで絞り込む。例えば、下記のようにしてデバグの手がかりにする使い方が考えられる。
まず、systemctl で ntpdサービスユニットの現在のPIDを調べる:
# systemctl status ntpd.service
Main PID: 679 (ntpd)
PID 679のプロセスのログエントリを詳しく見る:
# journalctl -x -e _PID=679
Journalフィールドフィルタのひとつ。プロセスのUIDでフィルタ。UIDは数値表記でないとヒットしない。よって、例えばこんな具合に使う。もちろん同様に _GID でのフィルタも可能。
# journalctl _UID=$(id -u ntp)
これもJournalフィールドマッチのひとつ。ログエントリの "prog[PID]:" (レガシーSYSLOGで言えばTAGフィールド) の prog 部分でフィルタリングする。
期間によるフィルタ。イコール記号はあってもなくてよい。今が 2016/07/14 00:15:00 だったと仮定して例によって示す。
ローカルタイムの今日 2016/07/14 00:00:00 から現在までのログエントリを表示:
# journalctl --since=today
下記もこれと同義。'00:00:00' は既定値なので省略可能で、指定する場合は年月日と時刻をまとめてクォートしないとエラーになる。
# journalctl --since '2016-07-14 00:00:00'
昨日7月13日の 00:00:00 から現在までのログエントリを表示:
# journalctl --since yesterday
これを下記のようにすると、感覚とは違って今日の分は含まれないので注意。
# journalctl --since yesterday --until today
`yesterday' が前日の 00:00:00 を意味するのに対して、`-1days' は相対的な24時間前の意味になるので同じではない:
# journalctl --since -1days
ここ2時間分のログを表示:
# journalctl --since -2h
ここ30分のログを表示:
# journalctl --since -30min
ディスク上の現在のジャーナルファイル合計サイズを表示する。アーカイブ(ローテーション)された分も含まれる。
ジャーナルファイルをトランケートする。トランケートの対象となるのはアーカイブされたジャーナルだけだ。時間基準で10日より前のエントリを削除するなら `journalctl --vacuum-time 10days'。単位には "s", "min", "h", "days", "months", "weeks", "years" が使えるとある。サイズ基準の場合は K, M, G, T (大文字小文字区別あり) が使え、アーカイブ総計サイズが指定したサイズに収まるところまで古いエントリが削除される。
ジャーナルファイルの論理的整合性チェックを行う。