最初に触ったUnixはVAX-11/785で動いていたUltrixだったので、自分は根っからのBSD派だ。これは大学の計算機室に鎮座していたマシンで、緑色しか表示できないCRTを搭載したVT端末を通して使うものだった。とはいえ、やることと言えばnewsの閲覧ぐらいだった。3年生になるころには研究室に入り浸るようになりSun3/4上のSunOSを使うようになったからだ。
ところが例のSolarisが出てきて、SunはSVR4になってしまった。インストールして最初に衝撃を受けたのが、termcapがなくなっていることだった。まあ、最初にそれを確認する自分もどうかと思うんだけど……。terminfoってなんだよ！ と怒り狂っていたことはよく覚えている。まあそれ以来、ずっとSVR4は嫌いだし、そういうわけでLinuxも嫌いなのだった。
しかし現代においては、Linuxは避けて通れないOSだ。なにしろ仮想化全盛となり、qemuベースのシステムを作った張本人としては……。Linuxに慣れるためには、と思って自宅のシステムを置き換えてみたら、だんだんマルチのOSをメンテナンスするのが面倒になって、結局今では全部Linuxで動かしている始末である。これは決してLinuxが好きになったという意味ではない。端末PCにWindowsを使い続けているからといってWindowsが好きなわけではないのと同じだ。妥協の結果、そうなってしまっているに過ぎない。
Linuxで特に嫌いなのが、伝統に敬意を払わないことだ。今回取り上げるjournaldもそうだ。なんでよりによってsyslogを置き換えちゃうのか……。いや、優れた後継プログラムに転換していくのは構わない。しかし名前や仕組みを大きく変えてしまうのはどうか、と思うのだ。まあこの辺の愚痴を書き連ねていると、あと100行ぐらいかかってしまうのでそろそろやめとこう。
/var/log/messagesが空っぽになった
自分が管理するサーバ一覧をみると、ざっと10台ぐらいのLinuxマシンが並んでいる。作った端からすぐ消してしまうようなマシンもあるが、このブログサーバのように恒久的にメンテし続ける必要があるマシンもある。それが10台ぐらいあるということだ。これらは定期的にアップデートしなくてはいけないし、ログに異常があればチェックもしたい。まあ24/365で常時監視するほど大切ではないが、脆弱性を突かれて乗っ取られるようなマヌケはしない程度に管理しておきたいワケである。
で、ときどきmessagesなどをチェックするのだが、いくつかのマシンでmessagesのサイズが0になっていることに気づいた。messages以外にも、secureやらmailやら、rsyslogが吐くファイルがほとんどすべて、空っぽになっているのだ。あれまあ。
どういう問題なのかなとググってみると、たとえばRHELのこんなページがヒットする。
が、rsyslogはjournaldから情報を取るからrsyslog.confをちゃんと設定しておいてね、と書いてあるだけだ。これは役に立たない。もうちょっと調べると、こんなBugzillaがあることが分かる。
問題のマシンもVMなので、これかもしれない。ワークアラウンドが示されているので試してみる……具体的には/var/lib/rsyslog/imjournal.stateというファイルを削除してrsyslogdを再起動してみな、というのだが、これでも解決しない。
journaldの導入でsyslogはどうなったか
ここでsyslogの仕組みをおさらいしてみよう。こういうときは古典に頼るに限る。詳解UNIXプログラミングのp.438-442に詳しく説明されている。図を引用しよう。
デーモンは、図中の中上のユーザプロセスにあたり、syslog(3)を呼んで/dev/logにメッセージを送る。syslogdはこれを経由してメッセージを受け取り、facilityとlevelに応じてファイルに書くとかなんとかするわけだ。ではjournald導入で何が変わったのだろうか？
journaldは元々syslogdのいた位置を占め、いったんすべてのメッセージを受け取る。またjournaldはこれ以外にも、たとえば systemd経由で起動したデーモンのSTDERRも受け取るようにできている。またjournaldは、syslogdが集めなかったメタ情報も集める。非常に細かな大量の情報を集めて、受け取ったメッセージと共にジャーナルとして保管する。このジャーナルは、デフォルトでは一時的な保管場所 /run/log/journal に保管される。この保管場所は小さいので時間が経つとすぐに消えてしまうし、リブートしても消えてしまう。そこで2つの選択肢がある。
- 恒久的な場所に保管するよう変更する。それでもサイズ上限はあるので、適度に広げる必要はある
- rsyslogを使って恒久化する。今度はrsyslogのサイズ上限があるので、適度に管理する必要が生じる
というわけで、rsyslogはちゃんと存在している。rsyslogはいまやjournaldから間接的にログを分けてもらう存在に成り下がっている。しかし、使い勝手は従来と同じだ。これで後方互換性は保たれるというわけだ（助かった）。
トラブルシュート
さてmessagesにログが残らない問題のマシンだ。まずloggerのソースをダウンロードしてみた。調べてみると、ふつーにsyslog(3)を使っているので一安心だ（journaldのAPIを直に叩いていたらどうしようかな、と思っていたのだ）。そこでsyslogを使ったごく小さなコードを書いて、問題が生じているマシンで再現実験をしてみた。
#include <stdio.h>
#include <syslog.h>
int main(void)
{
openlog("logtest", LOG_CONS | LOG_PERROR, LOG_USER);
syslog(LOG_USER | LOG_INFO, "this is test string");
return 0;
}しかし何をどうやってもmessagesには何も記録されない。どうもおかしい……と、ここで思い立ってjournalctlを使ってそちらに何が記録されているかを確認してみた。すると、そちらにも記録されていなかった。rsyslogの問題かと思っていたら、journaldからしてうまく動いていないようだ。はてさて、どういうことだろう……
と思っていたところで、ようやく思い出したことがあった。そういやフィルタを一つ入れていたぞ。
「systemdメッセージでログがあふれる」
CentOS7でmessagesを見ていると、Created sliceなんちゃら、とか Starting Sessionどうちゃら、というメッセージが大量に記録される問題に悩まされる。これはユーザがログインするたびに記録されてしまうのでうざったい。この問題をググると、こんなワークアラウンドが見つかる。
いわく、rsyslogにフィルタルールを書いて遮断せよ、とある。なるほどね、ということで言われるままにこれを入れた。
管理しているサーバが数台のうちはよかった。コピペするとかscpするなどして、都度対応していればよい。だがサーバ数が増えてくると、なんだが段々面倒くさくなってくる。こういうとき自分はどうしているかというと、アップデートスクリプトを使って対応する。それはどんなものかと言うと；
- 管理しているサーバ一覧 ~/etc/hosts.list がある
- それを順に読み取る
- sshログインして、一定の処理をする
- yum -y update とか
- package-cleanup -y –oldkernels とか
- Created sliceなんちゃらを抑制するフィルタがなければそれを追加するとか
で、その該当部分はこんな感じだった。
if grep 'release 7' /etc/redhat-release >/dev/null; then
if [[ ! -e /etc/rsyslog.d/ignore-systemd-session-slice.conf ]] ; then
echo 'if \$programname == "systemd" and (\$msg contains "Starting Session" or \$msg contains "Started Session" or \$msg contains "Created slice" or \$msg contains "Starting user-" or \$msg contains "Starting User Slice of" or \$msg contains "Removed session" or \$msg contains "Removed slice User Slice of" or \$msg contains "Stopping User Slice of") then stop' >/etc/rsyslog.d/ignore-systemd-session-slice.conf
systemctl restart rsyslog
fi
fiこれは修正後のコードだが、修正前は「$」がエスケープされていなかった。なので変数が実行前にすべて評価されてしまい、結果として壊れたフィルタルールがマシンに書かれてしまい、壊れたルールに従ってrsyslogがフィルタをしてしまうという状況に陥ってしまっていたのだった。messagesが空になっているマシンは、フィルタをこのスクリプトで処理しはじめた後のものばかりで、正常に動いていたものは手でコピペしていた世代のものだった。
問題の生じているマシンは、すべて壊れたフィルタが入っていたので、これらをすべて正しいフィルタに書き換え、リブートすることですべて正常に戻った。どっとはらい。
結局技術的には成長してない
原因調査を始めたときは、これを機にjournaldを完全に理解するぜーと意気込んだのだが、オチてしまうとやる気がなくなってしまっていけない。本来取り組むべきは、
- もうちょっとマシなサーバ管理機構を導入する
- ログ管理を一元化する。syslogを集めて一か所で見るとか
- fluentdみたいなモダーンな仕組みを試してみるとか
まあでも脆弱性を突かれない程度に管理できれば、まあいいか……