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

最近ではコンビニも通常通り開いているし，デパートの初売りも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=<lexie.davie@linet.gr.jp> 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 <fishley@linet.gr.jp>: Recipient address rejected: User unknown in local recipient table; from=<> to=<fishley@linet.gr.jp> 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=<jquinones@devida.gob.pe>, 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バラ撒きの踏み台にされているのかも知れません。そこで，より詳しくメールサーバのログを調べることにしました。