systemd-journaldを活用しよう

ゲストブログ
2015.07.16
Red Hat Enterprise Linux 7 ではsystemd-journald(以下journald)が導入されています。journaldは従来からあるsyslogと比較すると、細かな時間を表現できたり、ログの中に従来は失われていた優先度などの情報を保持できる、インデックスによる高速な検索、ログのローテートをjournald自身で行うなどの様々な特長を持っています。

レッドハットの森若です。今回は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ページが非常に充実しています。

    man systemd-journald.service

    man systemd.journal-fields

    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も対応するといいですね。