遅ればせながら明けましておめでとうございます。筆者の住んでいる関西地方は、年末こそやや冷えこんだものの、元日からはいい天気でおだやかな新年となりました。

最近ではコンビニも通常通り開いているし、デパートの初売りも1月1日からになってあまり年末年始の雰囲気は感じなくなりましたが、筆者が学生だったころは1月4日の初売りまではお店がどこも閉まっていて、暮れから正月三が日の間をいかに食いつなぐかが結構深刻な問題でした。

食べ物だけでなく、ネットワークの運用管理も年末年始は大変でした。最近では専門のプロバイダが1年365日、変らないレベルでサービスを提供してくれますが、当時は年末年始の休暇に入ると大学や企業のメールサーバやゲートウェイマシンも電源を落されてしまい、メールの経路が普段とは変っていたり、送信できないメールがたまってスプールが溢れたり、と普段は発生しないようなトラブルが起きることが年末年始の風物詩のようになっていました。

もっとも、賀状メールやSPAMが増加するため、現在でも年末年始には普段は見られないトラブルが起こりがちです。今回は、この年末年始に筆者が実際に経験したトラブルを元に、トラブル時のログファイルの調べ方の一例を紹介してみようと思います。

トラブル発生

今回発生したトラブルは、筆者がとりまとめ役をやっているPlamo Linuxのメーリングリスト（ML）に投稿したメールが配送されない、といったものでした。メールサーバ自体が止まったわけでも、MLサーバが止まったわけでもありません。投稿されたメールもほとんどは流れているけど、たまに流れないメールがある、という微妙な症状です。

この症状自体は年末のころから指摘されていましたが、当初はそれほど深刻なものとは思わず、何らかのタイミングの問題なのかなぁ…、と考えていました。しかし、自分の投稿したメールも配送されない状況を経験したこともあって、重い腰をあげて調査を始めました。

状況の確認

このようなトラブルでは、まずサーバの状況を確認することが重要です。sshを使ってメールサーバにログインすると、普段とは違ってずいぶんパスワードの入力やコマンドプロンプトの出力が遅れます。「⁠あれれ？」と思ってuptimeを見ると、load averageが20を超える値になっています。

「これはおかしい」と思って、ps axwwで動いているプロセスを見ると、httpdやsmtpのプロセスが普段の数倍増しで動いていることがわかりました。

以前からこのサーバでは、Webサービスを提供しているhttpdプロセスが長時間に渡って滞留してload averageを押しあげることがありました。今回も、topで動いているプロセスの状況をしばらく観察すると、メモリを大量に使用しているhttpdが常に上位に貼りついているようです。そこで、まず httpdプロセスを一度終了して再起動してみることにしました。

その結果、load averageは下り始め、システムの反応性も通常に戻ってきましたが、smtpのプロセスが大量に動いている状況は変りません。このマシンではメールサーバにPostfixを使っているので、メールサーバのログファイルである/var/log/maillogを調べてみました。

[root@fs kojima]# tail -f /var/log/maillog
 Jan  7 17:59:17 sv postfix/smtpd[30299]: connect from mx1.domainese.com[202.71.103.241]
 Jan  7 17:59:23 sv postfix/smtpd[30300]: connect from unknown[194.65.136.82]
 Jan  7 17:59:23 sv postfix/smtpd[30300]: NOQUEUE: reject: RCPT from unknown[194.65.136.82]: 450 Client host rejected: cannot find your hostname, [194.65.136.82]; from=<> to=<[email protected]> proto=ESMTP helo=<mail.normetro.pt>
 Jan  7 17:59:24 sv postfix/smtpd[30300]: disconnect from unknown[194.65.136.82]
 Jan  7 17:59:26 sv postfix/smtpd[30299]: NOQUEUE: reject: RCPT from mx1.domainese.com[202.71.103.241]: 550 <[email protected]>: Recipient address rejected: User unknown in local recipient table; from=<> to=<[email protected]> proto=ESMTP helo=<MX1.ecofasthost.com>
 Jan  7 17:59:26 sv postfix/smtpd[30299]: disconnect from mx1.domainese.com[202.71.103.241]
 Jan  7 17:59:35 sv postfix/smtp[30278]: connect to pop3.devida.gob.pe[190.12.82.70]: Connection timed out (port 25)
 Jan  7 17:59:35 sv postfix/smtp[30278]: BD551C9D845: to=<[email protected]>, relay=none, delay=35063, status=deferred (connect to pop3.devida.gob.pe[190.12.82.70]: Connection timed out)
 Jan  7 17:59:36 sv postfix/smtp[30293]: connect to pop3.devida.gob.pe[190.12.82.70]: Connection timed out (port 25)
 ...

ログファイルを調べるにはいくつかの方法がありますが、ここではtail -fというコマンドを使っています。tailコマンドはheadコマンドの反対で、ファイル末尾の10行ほどを表示するコマンドですが、そこに-fというオプションを付けることで、末尾を継続的に表示させています。このコマンドはCtrl-C等で強制終了させない限り、ファイルに新しい行が追加されるごとにその部分を表示してくれます。

上記の部分にはpostfix/smtpとpostfix/smtpdの2つのコマンドのログが示されています。Postfixの世界では、smtpdは外部のメールサーバからメールを受ける際、smtpは外部のメールサーバへメールを送信する際に利用されるコマンドです。また、このメールサーバではSPAM対策としてPostfixの設定ファイルで、IPアドレスから逆引きできないメールサーバからのメールは拒否する、ローカルに存在しないユーザへのメールは拒否する、といった設定を加えており、上記のログでは194.65.136.82からのメールは相手方のドメイン名を逆引きできないため、mx1.domainese.comからのメールはfishley@linet.gr.jpという宛先アカウントがローカルに存在しないため、それぞれ受け取りを拒否しています。一方、送信側のsmtpでは、jquinones@pop3.devida.gob.pe というアドレスに送信しようとしたメールが Connection timed outで送信に失敗していることがわかります。

SPAMがメール流量の9割近くを占めている現状では、このような受け取り拒否が生じることは珍しいことではありませんが、psで確認した際に送信側のsmtpのプロセスが多数生成されていたことは気になります。もしかしたら、このマシンがSPAMバラ撒きの踏み台にされているのかも知れません。そこで、より詳しくメールサーバのログを調べることにしました。

ログの分析

このマシンでは、メールサーバのログは週に一度 logrotate によってアーカイブされ、4週分保存されています。そこでまずログファイルのサイズを眺めてみました。

[root@fs kojima]# ls -lh /var/log/maillog*
 -rw-------  1 root root  78M Jan  7 19:01 /var/log/maillog
 -rw-------  1 root root 412M Jan  6 04:57 /var/log/maillog.1
 -rw-------  1 root root 255M Dec 30 05:45 /var/log/maillog.2
 -rw-------  1 root root 118M Dec 23 05:18 /var/log/maillog.3
 -rw-------  1 root root 119M Dec 16 04:45 /var/log/maillog.4

lsのオプションに指定している-lhは-lがファイルサイズや最終更新日を表示する指示、-hは人間が読みやすいようにKバイトやMバイト単位で表示する指示を意味し、それらを合わせた指定になります。

この結果を見ると、12月9日～16日、12月16日～23日の間は約120Mバイト程度だったログファイルが、12月23日～30日にかけて255Mバイトと倍増し、さらに12月30日～1月6日にかけては412Mバイトへと増加していることがわかります。

ファイルサイズを見るだけでも週単位でログファイルが急増していることがわかりますが、もう少し細かく見ればどうでしょう。今回のログファイルは上記のように1つが数百Mバイトのサイズなので、エディタで開くことは現実的ではありません。事実Emacsで開こうとすると "Maximum buffer size exceed" と言われて開くことができませんでした。一方、このような巨大なファイルでもlessやlvといったページャ（ビューワ）では表示可能でした。

このファイルは先に tail -f で見たログのような記録がエンエンと記録されているだけで、ざっと眺めたりerrorやwarningという単語をキーワードに検索をかけても、何か大きな問題が生じたためにログが急増したような気配はありません。そこでより細かく見るために、ログファイルの日付を元に1日単位に分解しました。

変化をより詳細に見るために、1日単位に分解したログファイルのサイズの変化をグラフ化してみました。

この結果を見ると、12月26日からのログが12月上旬の3～4倍に急増していることがわかります。当初、これは恐らくクリスマスから年末年始のホリデーシーズンを狙って、SPAMの類いが急増したことによるのだろう、と考えていました。

処理量が普段の4倍増しとなると、少々過負荷でトラブルが生じるのも仕方ないのかなぁ…、とも考えましたが、受信側（smtpd）だけではなく送信側（smtp）側のプロセスが多数動いているのが気になります。

より詳細な分析

そこで、日付別のログファイルからさらにpostfix/smtpd, postfix/qmgr、postfix/smtpの各プロセスのログを抽出してみました。それぞれのプロセスはsmtpdがメールの受信処理、qmgrがPostfix内部でのキューの管理、smtpがメールの送信処理をそれぞれ扱っています。

このデータも各プロセスごとのログファイルのサイズをグラフ化してみました。

この結果を見ると、smtpdの処理量は12月26日以降もそれほど変ってはいないものの、qmgrとsmtpの処理量が26日を境に爆発的に増加していおり、これらのせいでログファイルが急激に大きくなっていることが予想されます。そこで12月27日前後のsmtp、qmgrのログファイルをより詳しく調べてみました。

12月27日のsmtpのログを調べたところ、下記のようにConnection timed outやConnection refusedで送信に失敗したメールの再送が、繰り返し試みられていることに気がつきました。

 Dec 27 00:01:08 sv postfix/smtp[17635]: 90442C9CB29: to=<[email protected]>, relay=none, delay=150744, status=deferred (connect to uk.psi.com[62.50.72.146]: Connection timed out)
 Dec 27 00:03:01 sv postfix/smtp[17640]: 90442C9CB29: to=<[email protected]>, relay=none, delay=150857, status=deferred (connect to uk.psi.com[62.50.72.146]: Connection timed out)
 Dec 27 00:03:51 sv postfix/smtp[17622]: 90442C9CB29: to=<[email protected]>, relay=none, delay=150907, status=deferred (connect to uk.psi.com[62.50.72.146]: Connection timed out)

たとえばsmtpのログを調べると、この90442C9CB29というIDを持つメールは12月24日から12月30日にかけて、下表のような頻度で送信が試みられ、すべてConnection timed outになっています。12月31日で0になるのは、このメールサーバのキューの保持期間がデフォルトの5日間になっていて、その期間を越えたため削除されたせいでしょう。

それでは、このsally@uk.psi.com宛のメールはなぜ送信されようとしているのでしょう？ このアドレスを手掛かりにsmtpdのログを調べてみると、このアドレスをfrom行に指定したSPAMが大量に投稿され、その一部がPlamoメンテナMLのアドレスに送りつけられていたことがわかりました。

このメールサーバでは複数のMLをfmlで運用しており、そのうちPlamoのMLはユーザが多い分、SPAMが紛れ込むことも多いので、当初から非メンバーからの投稿は無視（ignore）する設定にしています。一方、メンテナMLはアドレスも長くて一般的ではないため、fmlのデフォルト動作である拒否（reject）にしたままになっていました。

fmlの場合、非メンバーからの投稿ポリシーをrejectに設定していると、非メンバーからの投稿に対して「あなたはMLのメンバーではありません、云々」といったメッセージが返信されます。SPAM等でfrom行が詐称されていると、この返信メッセージが行き先を失って、今回の例に見るように繰り返し送信が試みられ、その度にタイムアウトしてキューに戻され、一定の時間が経った後再度送信が試みられる、といった処理が行われてしまい、その結果として今回のトラブルの原因となったsmtpやqmgrプロセスが大量に動作する、という状況になったようです。

そこで、今回の対策としては、fmlで運用している各MLの設定を見直し、rejectポリシーになっている場合はignoreに変更すると共に、メールサーバのキューの保持期間を2日間に短縮して様子を見ることにしました。その結果、mailqで見るかぎり、まだ少しキューにメールが溜っているようですが、MLへの投稿は漏れずに配送されるようになったようです。

今回の例はログファイルの読み方というよりは、膨大な量のログをいかに分析するかに焦点を絞ったものになりました。数百Mバイトものログはそのまま分析することは困難なので、いかに効率よく必要な情報を抽出するかが鍵になります。sedやgrep、perlやawkといったUNIXのコマンドはこのような作業のために磨きあげられてきた、きわめて便利なツールです。