レッドハットの森若です。今回はRHEL7でロギングの仕組みとして導入されたsystemd-journaldを紹介します。journaldは従来のsyslogとは大きく異なっており様々な特長を持っています。デフォルトでは各種のログをrsyslogへ配送するための中継ぎとして構成されていますが、永続化して利用することで大変強力なツールとして活用できます。
journaldでのログはどこに保存されるのか?
デフォルトでは/run/log/journal/以下に保存されています。/run以下はtmpfsで、再起動などをすると消えてしまいます。
mkdir /var/log/journal すると/run以下ではなく/var以下に保存します。journaldを活用したいときは迷わず mkdir /var/log/journal しましょう。永続化することによりrsyslogと二重にログを保存することになりますが、ディスク容量を食う以外には特に悪いことは起きません。journaldで一本化できると確信ができたらrsyslogの利用をやめてしまってもかまいません。
実はこのディレクトリ構成はjournaldの特長である、起動直後からのログを統一した形で取り扱えるという性質に関連しています。
initramfs内で起動直後にjournaldを起動します。この時点ではroot fsをmountしていないので、まずはtmpfsで作成された/run 上にログ蓄積をはじめます。この状態のまま継続して動作することもできますが、初期化が順調に進んでroot fsをmountしたあとに、/var以下に/run以下のログを移動させる処理をおこなってログを永続化します。
systemd-journaldでのログ拡張
systemd-journaldではログを幅広く拡張しています。ログに含まれている情報の例を見てみましょう。
(アプリケーションが対応していれば)メッセージの文面によらない一意なIDやソースコード上の位置を付加できるためトラブルシュート時に活用しやすい
優先度が保持されるのでログ蓄積後に任意の優先度で検索できる
ログを送信したプロセスについての各種情報を保存しているのでIdentifierを正しく設定しないプログラムや偽装するプログラムへの対応にもなる
タイムスタンプがマイクロ秒単位となっており、クラスタ環境などで複数マシンにまたがっていてもログの前後関係が把握しやすい
下の図はログ1行分の出力例です。ピンク色の部分が従来のsyslogで保存されていた情報ですので、たくさんの情報が含まれていることがわかります。
ログの表示とフィルタによる検索
journaldのログはバイナリフォーマットになっているのでjournalctlコマンドにより表示をおこないます。journalctlコマンドをただ叩くと一番古いものからページャで表示されます。
単純に保存したログを読むだけでもよいのですが、journaldはそれぞれのフィールドを利用してフィルタを指定し、高速に検索できます。
実行ファイルでのフィルタ
journalctl /usr/bin/pcscd のように実行ファイルのパスをオプションとして渡すことで、実行ファイルによるフィルタをおこないます。
優先度によるフィルタ
journalct -p 4 のように数字0(emerg)から7(debug)までの間で優先度を指定します。たとえば4であればwarning以上の全ての優先度のログを表示します。
systemd unit でのフィルタ
systemdのunitでの絞り込みができます。systemdは関連プロセスを追跡しているため、子プロセスの出力も確認できます。たとえば journalctl -u NetworkManager とすることでNetworkManagerが呼びだす dhclientやModemManagerによるログも確認することができます。
複数条件によるAND検索
journalctl -p 4 /usr/bin/su のように複数の条件を指定することで「Warning以上の優先度で/usr/bin/suから出力されたもの」のようにAND検索による絞り込みがおこなえます。
その他にも起動毎のBOOT IDを保持しているので「journalctl -b -1」として前回の起動時からのログを見たり「journalctl -k」としてカーネルから出力されたログのみを確認することができます。
ログ表示フォーマットの変更
journalctlのデフォルトでは読みだした内容を馴染み深いsyslog風にフォーマットしてくれます。しかしjournaldが保持している情報をどう整形するかは -o オプションで選択できます。
journalctl -o short-precise 時刻のみをマイクロ秒単位の表記にし、あとはsyslog風のまま
Jul 16 16:04:11.535406 rhel71.example.com systemd-journal[104]: Runtime journal is using 6.2M (max 49.6M, leaving 74.4M of free 490.2M, current limit 49.6M).
journalctl -o json 全てのフィールドを含んだJSON形式での出力
{ "__CURSOR" : "s=ef196eeafe92413cba33aab060cb9029;i=1;b=58f89813972d401ba3591da7067616a3;m=ad1eb;t=51af8adac9c2e;x=cce32c6f2c25f849", "__REALTIME_TIMESTAMP" : "1437030251535406", "__MONOTONIC_TIMESTAMP" : "709099", "_BOOT_ID" : "58f89813972d401ba3591da7067616a3", "PRIORITY" : "6", "_TRANSPORT" : "driver", "MESSAGE" : "Runtime journal is using 6.2M (max 49.6M, leaving 74.4M of free 490.2M, current limit 49.6M).", "MESSAGE_ID" : "ec387f577b844b8fa948f33cad9a75e6", "_PID" : "104", "_UID" : "0", "_GID" : "0", "_COMM" : "systemd-journal", "_EXE" : "/usr/lib/systemd/systemd-journald", "_CMDLINE" : "/usr/lib/systemd/systemd-journald", "_CAP_EFFECTIVE" : "4402800cf", "_SYSTEMD_CGROUP" : "/system.slice/systemd-journald.service", "_SYSTEMD_UNIT" : "systemd-journald.service", "_SYSTEMD_SLICE" : "system.slice", "_SELINUX_CONTEXT" : "kernel", "_MACHINE_ID" : "1e5c5682191d4edcbdb0ff3725e3fdc1", "_HOSTNAME" : "rhel71.example.com" }journalctl -o export export/import用のテキスト形式
__CURSOR=s=ef196eeafe92413cba33aab060cb9029;i=1;b=58f89813972d401ba3591da7067616a3;m=ad1eb;t=51af8adac9c2e;x=cce32c6f2c25f849 __REALTIME_TIMESTAMP=1437030251535406 __MONOTONIC_TIMESTAMP=709099 _BOOT_ID=58f89813972d401ba3591da7067616a3 PRIORITY=6 _TRANSPORT=driver MESSAGE=Runtime journal is using 6.2M (max 49.6M, leaving 74.4M of free 490.2M, current limit 49.6M). MESSAGE_ID=ec387f577b844b8fa948f33cad9a75e6 _PID=104 _UID=0 _GID=0 _COMM=systemd-journal _EXE=/usr/lib/systemd/systemd-journald _CMDLINE=/usr/lib/systemd/systemd-journald _CAP_EFFECTIVE=4402800cf _SYSTEMD_CGROUP=/system.slice/systemd-journald.service _SYSTEMD_UNIT=systemd-journald.service _SYSTEMD_SLICE=system.slice _SELINUX_CONTEXT=kernel _MACHINE_ID=1e5c5682191d4edcbdb0ff3725e3fdc1 _HOSTNAME=rhel71.example.com
journaldへのログ送付
journaldへログ出力するにはどうすればいいのでしょうか? 拡張機能を利用しないのであれば、従来のsyslogとおなじように利用できます。
たとえばloggerコマンドを以下のように実行すると
# logger “foobar”
このようなログが保存されます。
__CURSOR=s=ef196eeafe92413cba33aab060cb9029;i=b32;b=58f89813972d401ba3591da7067616a3;m=222d7fb47;t=51afad079c589;x=b44e2b3141f0b6eb __REALTIME_TIMESTAMP=1437039425340809 __MONOTONIC_TIMESTAMP=9174514503 _BOOT_ID=58f89813972d401ba3591da7067616a3 _UID=0 _GID=0 _MACHINE_ID=1e5c5682191d4edcbdb0ff3725e3fdc1 _HOSTNAME=rhel71.example.com PRIORITY=5 _TRANSPORT=syslog SYSLOG_FACILITY=1 SYSLOG_IDENTIFIER=root MESSAGE=foobar _PID=18822 _SELINUX_CONTEXT=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 _SOURCE_REALTIME_TIMESTAMP=1437039425340049
アプリケーション用には、標準でCとPython用のライブラリが用意されています。systemd作者のLennertのblogに開発者むけの利用例が記載されています。
関連資料
systemdはmanページが非常に充実しています。
systemd作者のblogにも解説があり参考になります http://0pointer.de/blog/projects/journalctl.html
早くからsystemdを採用していたArch Linuxのwikiには利用に関するhowtoの知識が蓄積されています。
https://wiki.archlinuxjp.org/index.php/Systemd
小ネタ
ページャで行を折り返したい
journalctlで表示をするときに、デフォルトでは行を折り返さずに長い行は横スクロールで読むように設定されています。lessのデフォルトと異なっているのでおどろく方もいるかと思います。
環境変数 SYSTEMD_LESS にページャへのオプションを指定することで折り返しの表示にすることができます。lessの行折り返しをしないオプションは-Sですので、デフォルトの”FRXSMK”からSをのぞいて以下のようにオプションを指定します。
export SYSTEMD_LESS=FRXMK
もろもろの事情で環境変数の設定がむずかしい場合、journalctl -b | less のようにパイプで接続することでオプションなしのlessが利用できます。
tailf /var/log/messages のような監視がしたい
tailfに近い動作をする「journalctl -f」として出力をリアルタイムで継続的に監視できます。この時もフィルタを利用できるので、tailとgrepを利用するよりも便利なケースも多いはず。
シェルでいろいろ属性がついたログ出力をしたい
Fedora 22に含まれているutil-linux ではloggerコマンドに–journald オプションが追加されており、journaldが処理できる各種の属性を付加したログ出力が可能になっています。RHEL7.1で確認したところまだ対応していないので、はやくRHELのutil-linuxも対応するといいですね。
