ついこの間新年を迎えたと思ったのに、いつの間にか1年の12分の1が過ぎ去ってしまいました。この時期は何かと行事や雑用が多く、油断しているとあっと言うまに新年度になってしまいそうです。子供のころ、大人たちが「1月はいってしまう、2月はにげてしまう、3月はさってしまう」と言っているのを聞いておもしろいと思ったことがありますが、その表現を実感として感じる年齢になってきたようです。
Plamo Linuxの状況
諸般の事情で去年はメンテナンスリリースしかできなかったPlamo Linux ですが、新しいOSS環境に追従するためのバージョンアップを目指して、1月の中旬くらいからGCC-4.2.2 やglibc-2.7、X11R7.3 など最新の環境をいじりはじめました。当初はインストーラやパッケージ管理の仕組みの改善も含めた大規模な改修を目指していましたが、賞味期限が切れているソフトウェアの更新だけでもかなりな規模になりそうなので、まずは新しいバージョンのソフトウェアできちんと動く環境を整えることを目標に作業を進めています。
最近のX Window Systemや日本語入力システム(インプットメソッド)などをいじって感じるのは、外部のライブラリへの依存性がずいぶん高くなってきたことです。たとえばX Window Systemの場合、かってはライブラリの依存関係の管理やMakefileの生成などを行う専用のツールを含めた巨大なソースコード一式を用意して、外部環境への依存をできるだけ減らしていましたが、X11R7以降ではOSSで標準的なGNU autoconf/automakeの仕組みを導入すると共にソースコードを分割、モジュール化して、パーツごとの開発を容易にする方向に大きく変化しています。
従来のX Window Systemでは、メーカごとにさまざまに異なるワークステーション環境でも利用可能にするため、便利だけれどOSに依存する独自コマンドなどは使わず、UNIX互換環境ならば必ず存在するであろう最小限のコマンドだけを使ってかなりトリッキーな処理を行っていた部分がありましたが、OSSの便利なツールを前提とすることで、それらの見通しがずいぶんよくなった印象を受けます。
かってのX Window Systemは "make World"
というコマンド1つですべてのソースコードをコンパイルしていきました。メーカごとに異なる各種ワークステーション環境の違いを吸収し、あらゆるUNIX互換OSに存在する最小限のSoftwaretoolsのみを使って環境を構築していくそのあり様は、まさに天地創造 (make World)と呼ぶにふさわしい壮大で複雑なメカニズムでした。
一方、外部環境に大きく依存するようになった結果、X Window Systemのソースコードやドキュメントだけでは解決できないような問題も生じてきて、freetypeやD-bus、expatといった外部環境まで意識する必要が生じてきたのはディストリビューションのメンテナにとって頭の痛い問題です。読んだり調べたりしなければいけない資料はX Window Systemの世界だけに閉じていませんし、必要となる外部環境もどんどんバージョンが更新されて、旧来のやり方が通じなくなることもよくあります。
システムが進化していくにつれ、この種の高度で複雑な相互依存関係が生じることは避けられないでしょう。OSSの特徴である「バザール」モデルが、このような高度で複雑な相互依存性とどのように折りあっていくかは研究テーマとしても興味深いところです。
メールサーバのログ再考
Plamo Linuxの新版の話はまた改めて紹介することにして、今回は前回報告したメールサーバのトラブルとその対策についての後日談をとりあげようと思います。前回、メーリングリストのポリシー変更やメールキューの保持時間の短縮という対策を施したメールサーバですが、その後1ヵ月ほどのログファイルのサイズを調べると、図1のような結果になりました。
図1 Postfixプロセス別ログファイルサイズの変化
12/25ごろから急増しだしたsmtp、mailqの処理量(=ログファイルのサイズ)も、1/6の深夜に施した対策が奏功したのか、約2日後の1/9にはmaiq, smtpともに12月上旬のレベルに落ち着いてきましたし、自分の関係しているメーリングリストの配送も遅延なく行われているようです。
この結果を見ると「問題が解決してよかったね」という感じですが、あまりに出来すぎのような気がして、もう少しログファイルを調べてみることにしました。
ワインバーグ先生が『ライト、ついてますか』の中で繰り返し指摘しているように「すべての解答は次の問題の出所 」ですし、うまくいった解答ほど、次のより大きな問題を生み出しがちなことは今までに何度も経験しているので、今回の例のようにあまりに出来すぎな例には直感的な不信感を感じてしまいます。
まずは、メールサーバのログからメールを受信する役割を果たしているsmtpdのログ を抽出した上で、1日単位で受信拒否件数と受信受諾件数を抽出してみました。前回紹介したように、このメールサーバではSPAMの受け取りを少しでも減らすために、ドメイン名の逆引きができないホストからの接続とローカルに存在しないアカウントへのメールは受信拒否するように設定しており、この条件で受信拒否された接続はログに'reject'
と記録されます。一方、これらの条件を満してメールを受けつけた接続にはキューIDが割り当てられた上で'client=...'
と記録されるので、これらをキーワードに用いて出現頻度を1日ごとにカウントしてみました。
図2 smtpdが拒否するメール(reject)と受け付けるメール(accept)のカウント数の変化
この結果を見ると、メールを受け付けた件数はこの2ヵ月間ほぼ2,000件前後で推移しているのに対し、受信拒否の件数は15,000から30,000件の幅で推移しており、かなりバラツキが見られることもわかりました。しかし、今回のトラブルが発生した12月末から1月頭にかけて特に目立った変化は確認できず、この時期にSPAMの流量が特に増加したというわけではないようです。
このグラフを見ると「アドレスが登録されている(逆引きができる)サーバ」から「ローカルに存在するアカウント」に対して送信する、という最低限のルー ルに限っても、それを守っているメール(accept)に比べて守っていないメール(reject)は10倍近くになっていることが見てとれます。もちろん、このルールを守っているメールでも10通のうち8通くらいはSPAMだったりするので、昨今のSPAM とHAM(受け取りたいメール)の比は100:1 といっても過言ではないようです。
次に送信側の状況を調べるためにsmtpのログ を調べてみました。postfixで送信側の機能を果たすsmtpでは、正しく接続先に送れたメールは'status=sent'
(送信済み)と記録され、何らかの理由で送信できなかったメールは'status=deferred'
(送信延期)と記録されます。そこで、smtpdのログ同様、1日ごとにそれぞれのキーワードの出現回数をカウントしました。
図3 smtpが送信できたメール(sent)と送信できなかったメール(deferred)のカウント数変化
この結果を見ると、12月の中旬くらいまでは多少の変動はあるものの、送信済みメールも送信延期されたメールも2,000件から5,000件前後で推移しているのに対し、12/26から送信延期(deferred)されたメールが急激に増加していることが見てとれます。
前回述べたように、当初、この送信延期の原因は、Plamo LinuxのメンテナMLがrejectポリシーになっていたために、SPAMの送り主に「メンバー外メール」の通知を返そうとしたことによるものと考えていましたが、smtpdのログを元に、メンテナML宛に届いたメールの数を調べると、かなりバラツキはあるものの、この2ヵ月間はおよそ1日あたり200から500通で推移していて、特に12/26以降に急増した気配はありません。前回見たようにrejectポリシーによる詐称アドレスへのリプライメールは確かに発生しているものの、それだけで送信延期がこのように大量発生することは考えにくいところです。
頻出キーワードを絞り込む
そこで改めて送信延期が大量発生している時期のsmtpのログを眺めていると、いくつか特定のドメインが繰り返し現われていることに気がつきました。そこで、頻出しているac.jpドメイン2つ(A大学とB大学)と某大手プロバイダ(Cプロバイダ)の出現頻度をカウントしてみたところ、図4のような結果となりました。
図4 特定ドメインがログに出現した頻度の変化
このうちB大学の例は、12/27から送信延期が発生し始めたものの1/4には収束しています。この例はおそらく「年末年始の休暇でマシンが止まってしまった」といった類のトラブルでしょう。一方、A大学の場合はもう少し収束に時間がかかり、1/10くらいまで送信延期が発生していたようです。こちらも引き金は年末の休暇のようですが、休暇が終わってマシンが復旧して解消したのか、1/6の深夜にメールキューの保持期間を短かくしたため、送信されないままキューにたまったメールが削除されたのかはよくわかりません。
一方、Cプロバイダの例は多少傾向が異なっていて、A、B大学のように"Connection timed out"による送信延期ではなく、相手のメールサーバから451というエラーコード が返ったことによる送信延期のようです。
Dec 31 00:06:49 sv postfix/smtp[23229]: 66B72C9D18A: host XXXX said: 451 4.3.2 Please try again later (in reply to RCPT TO command)
SMTPの応答コード451は「ローカルエラーの発生 (local error in progress)」によると定義されており、具体的にどういうエラーが発生したかは不明ですが、おそらく「ユーザのメール使用量が制限値を越えた」といったエラーのように思われます。Cプロバイダの場合は、年末年始もサーバは問題なく動いていたものの、ユーザが休暇でメールのチェックを怠り、その結果メールの使用量が制限値を越えてしまったため送信延期が発生した、と考えるのがよさそうです。ただし、12月の中旬から延期が発生し始め、年末年始を越えた1月の中旬以降も同程度の送信延期が残っているところを見ると、ユーザの休暇以外の要因も疑われるところです。
以上のようにメールサーバのログを詳しく分析してみると、今回のトラブルにはメーリングリストの運用ポリシーだけではなく、年末年始休暇の影響もかなり大きいことが見えてきました。その意味では、今回の問題は特に対策を講じなくても、休暇が終われば解決した問題かも知れません。しかしながら、年末年始の時期に再度同じような問題が発生する可能性を未然に防ぐ意味でも、今回の対策は価値があったように思います。
従来、メールサーバでは「メールは可能な限り届ける」ために、キューの保持期間などは安全側に振るように設定されてきました。しかし、最近のようにSPAMが猖獗を極めている状態では「正しくないメールは積極的に除去する 」ようなルールも必要になることが、今回の調査からも見えてきました。この経験を踏まえて、より適切なメールサーバの設定を詰めていきたいと考えています。