金曜の昼に、お客様から「メールがなかなか届かない」という第一報が入りました。
メールマガジンを発行するために、Mailman というメーリングリストシステムを使っています。試しに会員登録をしてみたが、仮登録メールがなかなか届かないとのこと。
このサーバはお名前.com の VPS で、Mailman、WordPress、Subversion、Redmine などなど、いろいろなサービスを動かしているので、問題が複雑に見えてしまいました。
原因が分かった今となっては、「なんであの時気がつかなかったのか！」と思うことばかりですが、臥薪嘗胆の意味を込めて、恥を公開しておきます。
不運その１
原因究明に時間がかかってしまった要因として、問題発生ごろにバックアップが動いてしまったことです。
通常ならば深夜に動かしていたのですが、前の晩はバックアップ先の都合で動かしていなかったため、昼にバックアップが動いていました。
運用に支障をきたすわけにもいかないので、バックアップを途中で止めてサーバを再起動をかけました。
お名前.com の VPS は、コントロールパネルが分かりやすくて、再起動も簡単なのが嬉しいです。
再起動後は、たまっていたメールも無事に届き、通常稼働に戻りました。
実はバックアップが原因ではなかったのですが、たまたまバックアップが動いていたのでこっちに気をとられてしまいました。
原因その１と対策
ところが、しばらくするとまたサーバープロセスが終了していました。
もちろんバックアップは動いていません。
再起動をかけてログを見ると、/var/log/dovecot.log に異変が。
:
Jun 21 10:43:07 auth(default): Info: client out: FAIL 1 user=staff
Jun 21 10:43:07 auth(default): Info: client in: AUTH 1 PLAIN service=pop3 lip=XXX.XXX.XXX.XXX rip=XXX.XXX.XXX.XXX lport=110 rport=35433 resp=AHN0YWZmADEyMzQ=
Jun 21 10:43:07 auth(default): Info: passwd-file(staff,XXX.XXX.XXX.XXX): lookup: user=staff file=/etc/dovecot/mail.passwd
Jun 21 10:43:07 auth(default): Info: passwd-file(staff,XXX.XXX.XXX.XXX): unknown user
Jun 21 10:43:07 auth(default): Info: new auth connection: pid=25939
Jun 21 10:43:08 pop3-login: Info: Disconnected (auth failed, 1 attempts): user=, me
thod=PLAIN, rip=XXX.XXX.XXX.XXX, lip=XXX.XXX.XXX.XXX
: というようなログが2秒くらいごとに出ていました。
いわゆる、辞書攻撃というやつです。
メールアドレスを集めるために、いろいろなユーザ名で辞書順にアクセスしてくるという攻撃です。中にはメールアドレス収集ではなくサーバ停止が目的の場合もあります。
攻撃元は海外のIPアドレスでした。ここで晒してやりたいのは山々ですが、たぶん不正中継をさせられているだけだろうから、やめます。不正中継させているようなサーバを晒すと、さらに悪用されかねませんし。
あれよあれよという間にCPUの使用率が上がっていき、ハングアップしてしまいました。
そのサーバではPOP接続しないので、ファイアウォールの設定で、110番ポートをふさいでおきました。
原因その２（？）と対策
念のため、他のログも見てみると、httpd のerror_logに エラーが。
[Mon Jun 21 09:40:10 2010] [error] [client xxx.xxx.xxx.xxx] PHP Fatal error: Allowed memory size of 33554432 bytes exhausted (tried to allocate 182597 bytes) in /var/www/vhosts/xxx.xxxx.xxx/httpdocs/wordpress/wp-includes/wp-db.php on line 480, referer: http://xxx.xxxx.xxx/wordpress/wp-admin/
このエラーが出始めた頃と、サーバ停止が頻発しだした頃が合致しています。
WordPress のプラグインを使いすぎて、メモリを食うようになってきたのでしょう。
これも対策を打っておいた方がよさそう。
そこで、/etc/php.ini を修正。
;memory_limit = 16M ; Maximum amount of memory a script may consume
memory_limit = 64M ; Maximum amount of memory a script may consume
とりあえず、PHPで使えるメモリを64MBまで増やしました。
原因その３と対策
ところがまた停止しました。頻度は下がったものの、まだサーバが停止するのです。
「これ以上時間をかけるなら、再インストールしたほうがまし」と必要なファイルを集めていたとき、root 宛のメールを見ていないことに気がつきました。
すると、/root/Maildir/new に１万件以上のメールが溜まっていました。
時刻を見ると5分毎。
:
From: root@smtp.xxx.xxx (Cron Daemon)
To: mailman@smtp.xxx.xxx
Subject: Cron /usr/lib/mailman/cron/gate_news
:
Date: Mon, 21 Jun 2010 22:20:01 +0900 (JST)
/bin/sh: /usr/lib/mailman/cron/gate_news: Permission denied
つまり、cronで5分毎に実行しようとしているファイルに実行アクセス権がないとのこと。
ls -l /usr/lib/mailman/cron/gate_news で見てみると確かに実行権はついていません。
むむむ。このファイルはプレインストールされていたもので、触った覚えはないのだが・・・。
たまったメールを find /root/Maildir/new/ -mtime +3 -delete で、3日以前のメールを削除してから、chmod +x /usr/lib/mailman/cron/* で、cronが実行しようとしているファイルに実行権をつけ、再起動すると・・・。
その後は問題なく稼働し始めました。
関係ありそうな記事
Tips の記事