%=========================================================== % 地球惑星専攻サーバ トラブルカルテ % 日付 : 2004/06/04 % サーバ: mail % 文責 : 森川 靖大 %----------------------------------------------------------- ■ 目次 ・ 症状 ・ 原因 ・ 対処の方針 ・ 対処の作業ログ ・ 今後の長期的対応 ・ 参考資料 ・ おまけ ■ 症状 メールサーバの各ユーザのメールボックス (Mailbox や Maildir 等) に メールが配送されなくなった. ・ 特徴: - 専攻メールサーバ自身および外部のメールサーバからの, 全てのメー ルが専攻メールサーバの各ユーザのメールボックスに配送されない. - 専攻メールサーバから外部のメールサーバにメールを送ることは可能. - 専攻メールサーバのキュー (/var/qmail/queue) 以下にメールは 溜まる. (つまり, qmail にメール受け取ってもらうことはできる). ■ 原因 ・ qmail-local が同時に起動できる最大数である 10 まで溜まってしまった. そのため, 新たな qmail-local が起動できず, ローカル配送が 止まってしまっていた. 〔この「10」に関しては下記の参考資料 1 を参照のこと〕 【上記の原因】 - To:rotty-***@ep.sci.hokudai.ac.jp となっているメールはローカ ル配送用の qmail-local で配送される. /var/qmail/alias/.qmail-rotty-*** が存在するので, その中で指 定されるところに配送される. (特に rotty-epnetfan@〜へは, epnetfan-ml にメールが送られる度に配送されるため, 頻繁に配送 が行なわれる.) - /var/qmail/alias/.qmail-rotty-*** には, |/usr/local/bin/mail2news.pl rotty.*** と記述されるので, /usr/local/bin/mail2news.pl を起動する. (ちなみにこの段階で qmail-local のプロセスは停止していない) - mail2news.pl は内部で inews を用い, news サーバに記事を送ろ うとする. - 05/23, 06/03 あたりで news サーバが断続的に停止したため, その際に起動した inews, /usr/local/bin/mail2news.pl, qmail-local がそれぞれ, プロセスを残したまま事実上停止. 徐々にそういった不良プロセスが蓄積. - 06/04 01:27 に, とうとう qmail-local の不良プロセスが 10 個 になる. 〔mail2news.pl の設定等に関しては下記の参考資料 2 を参照のこと〕 【qmail-send → qmail-local までの概要】 - qmail-send はメールキューに溜まったメッセージを配送するための プログラムで, ローカルに配送するのに qmail-lspawn を, リモートに配送するのに qmail-rspawn を用いる. - qmail-lspawn はそれぞれ配送するメッセージ毎に qmail-local を起動し, メッセージを配送する. 〔qmail プログラムに関しては下記の参考資料 3,4 を参照のこと〕 ■ 対処の方針 残っている mail2news.pl, inews, qmail-local の不良プロセスを 削除することで, あらたな qmail-local が起動できるようにする. ■ 対処の作業ログ ・ 現在の配送状態の確認 まず, 以下のコマンドで再度配送を促す. # kill -ALRM 〔このコマンドに関しては, 下記の参考資料 5 を参照のこと〕 そして /var/log/mail.log を確認する. Jun 4 13:13:09 grey qmail: 1086322389.220351 delivery 2084188: deferral: Sorry,_I_wasn't_able_to_establish_an_SMTP_connection._(#4.4.1)/ Jun 4 13:13:09 grey qmail: 1086322389.204654 status: local 10/10 remote 1/20 1 行目の「deferal: Sorry 〜」で配送に失敗したことがわかる. 2 行目の「local 10/10」が 1) ローカル配送, 2) 現在の qmail-local 起動数, 3) 同時起動可能の最大数 を意味している. この表記から, 既に起動している qmail-local の数が 10 に到達していることが分かる. (ちなみにその右の「remote 1/20」がリモート配送に関するステータス) ・ 溜まっているメッセージの量の確認 - メッセージ全体のサイズを調べる # du -sh /var/qmail/queue/mess 22M /var/qmail/queue/mess (結構溜まっている) - メッセージの数を調べる # ls /var/qmail/queue/mess/*/* |wc 1987 1987 30213 (2000 通近く溜まっている) # 追記： qmail-qstat のコマンドで溜まった queue の数を調べることができる。 ・ プロセスの確認 それぞれ, qmail-local, mail2news.pl, inews のプロセスを確認する. 詳細は下記に記してあるが, 結果として, それっぽい怪しいプロセスが いっぱい発見される. $ ps aux | grep qmail-local alias 17782 0.0 0.0 1260 4 ? S May23 0:00 bin/qmail-local -- alias /var/qmail/alias rotty-epnetfan - rotty-epnetfan ep.sci.hokudai.ac.jp epnetfan-ml-return-4242-rotty-epnetfan=ep.sci.hokudai.ac.jp@ep.sci.hokudai.ac.jp ./Mailbox alias 14921 0.0 0.0 1260 4 ? S May23 0:00 bin/qmail-local -- alias /var/qmail/alias rotty-epnetfan - rotty-epnetfan ep.sci.hokudai.ac.jp epnetfan-ml-return-4243-rotty-epnetfan=ep.sci.hokudai.ac.jp@ep.sci.hokudai.ac.jp ./Mailbox alias 22652 0.0 0.0 1260 4 ? S May23 0:00 bin/qmail-local -- alias /var/qmail/alias rotty-epnetfan - rotty-epnetfan ep.sci.hokudai.ac.jp epnetfan-ml-return-4244-rotty-epnetfan=ep.sci.hokudai.ac.jp@ep.sci.hokudai.ac.jp ./Mailbox alias 32407 0.0 0.0 1260 4 ? S May23 0:00 bin/qmail-local -- alias /var/qmail/alias rotty-epnetfan - rotty-epnetfan ep.sci.hokudai.ac.jp epnetfan-ml-return-4245-rotty-epnetfan=ep.sci.hokudai.ac.jp@ep.sci.hokudai.ac.jp ./Mailbox alias 24587 0.0 0.0 1260 4 ? S May24 0:00 bin/qmail-local -- alias /var/qmail/alias rotty-epnetfan - rotty-epnetfan ep.sci.hokudai.ac.jp epnetfan-ml-return-4246-rotty-epnetfan=ep.sci.hokudai.ac.jp@ep.sci.hokudai.ac.jp ./Mailbox alias 10304 0.0 0.0 1260 296 ? S Jun03 0:00 bin/qmail-local -- alias /var/qmail/alias rotty-epnetfan - rotty-epnetfan ep.sci.hokudai.ac.jp epnetfan-ml-return-4279-rotty-epnetfan=ep.sci.hokudai.ac.jp@ep.sci.hokudai.ac.jp ./Mailbox alias 6795 0.0 0.0 1260 228 ? S Jun03 0:00 bin/qmail-local -- alias /var/qmail/alias rotty-epnetfan - rotty-epnetfan ep.sci.hokudai.ac.jp epnetfan-ml-return-4280-rotty-epnetfan=ep.sci.hokudai.ac.jp@ep.sci.hokudai.ac.jp ./Mailbox alias 13879 0.0 0.0 1260 228 ? S Jun03 0:00 bin/qmail-local -- alias /var/qmail/alias rotty-epnetfan - rotty-epnetfan ep.sci.hokudai.ac.jp epnetfan-ml-return-4281-rotty-epnetfan=ep.sci.hokudai.ac.jp@ep.sci.hokudai.ac.jp ./Mailbox alias 31220 0.0 0.0 1260 228 ? S Jun03 0:00 bin/qmail-local -- alias /var/qmail/alias rotty-test - rotty-test ep.sci.hokudai.ac.jp Odessa@better-svc-plans.com ./Mailbox alias 11669 0.0 0.0 1260 256 ? S 01:27 0:00 bin/qmail-local -- alias /var/qmail/alias rotty-epnetfan - rotty-epnetfan ep.sci.hokudai.ac.jp epnetfan-ml-return-4282-rotty-epnetfan=ep.sci.hokudai.ac.jp@ep.sci.hokudai.ac.jp ./Mailbox $ ps aux | grep mail2news alias 17784 0.0 0.0 2344 4 ? S May23 0:00 /usr/bin/perl /usr/local/bin/mail2news.pl rotty.epnetfan alias 14931 0.0 0.0 2348 4 ? S May23 0:00 /usr/bin/perl /usr/local/bin/mail2news.pl rotty.epnetfan alias 22668 0.0 0.0 2344 4 ? S May23 0:00 /usr/bin/perl /usr/local/bin/mail2news.pl rotty.epnetfan alias 32414 0.0 0.0 2344 4 ? S May23 0:00 /usr/bin/perl /usr/local/bin/mail2news.pl rotty.epnetfan alias 24589 0.0 0.0 2348 4 ? S May24 0:00 /usr/bin/perl /usr/local/bin/mail2news.pl rotty.epnetfan alias 10306 0.0 0.1 2352 1060 ? S Jun03 0:00 /usr/bin/perl /usr/local/bin/mail2news.pl rotty.epnetfan alias 6797 0.0 0.1 2348 992 ? S Jun03 0:00 /usr/bin/perl /usr/local/bin/mail2news.pl rotty.epnetfan alias 13883 0.0 0.1 2348 992 ? S Jun03 0:00 /usr/bin/perl /usr/local/bin/mail2news.pl rotty.epnetfan alias 31222 0.0 0.1 2348 992 ? S Jun03 0:00 /usr/bin/perl /usr/local/bin/mail2news.pl rotty.test alias 11671 0.0 0.1 2348 1004 ? S 01:27 0:00 /usr/bin/perl /usr/local/bin/mail2news.pl rotty.epnetfan $ ps aux | grep inews alias 17785 0.0 0.0 1540 4 ? S May23 0:00 /usr/bin/inews -h alias 14933 0.0 0.0 1540 4 ? S May23 0:00 /usr/bin/inews -h alias 22672 0.0 0.0 1540 4 ? S May23 0:00 /usr/bin/inews -h alias 32415 0.0 0.0 1540 4 ? S May23 0:00 /usr/bin/inews -h alias 24594 0.0 0.0 1540 4 ? S May24 0:00 /usr/bin/inews -h alias 10307 0.0 0.0 1540 548 ? S Jun03 0:00 /usr/bin/inews -h alias 6798 0.0 0.0 1540 100 ? S Jun03 0:00 /usr/bin/inews -h alias 13884 0.0 0.0 1540 548 ? S Jun03 0:00 /usr/bin/inews -h alias 31223 0.0 0.0 1540 548 ? S Jun03 0:00 /usr/bin/inews -h alias 11672 0.0 0.0 1540 580 ? S 01:27 0:00 /usr/bin/inews -h ・ 不良プロセスの掃除 それぞれ, 上記の qmail-local, mail2news.pl, inews の不良プロセス を消す. (qmail-local だけではなく, 関係する全ての不良プロセスを 削除しないといけないことに注意!!!) # kill <上記の qmail-local の PID> # kill <上記の qmail-mail2news.pl の PID> # kill <上記の qmail-inews の PID> ・ 配送状態のチェック 以下のコマンドで再度配送を促す. # kill -ALRM 〔このコマンドに関しては, 下記の参考資料 5 を参照のこと〕 そして /var/log/mail.log を確認する. Jun 4 13:54:09 grey qmail: 1086324849.719683 delivery 1914980: deferral: qmail-local_crashed./ Jun 4 13:54:09 grey qmail: 1086324849.719746 status: local 9/10 remote 0/20 Jun 4 13:54:09 grey qmail: 1086324849.719768 starting delivery 2084308: msg 1417777 to local morikawa@ep.sci.hokudai.ac.jp 1 行目の「deferal: qmail-local_crashed./」で qmail-local が強制的に 終了したことが分かる. 2 行目の「local 9/10」で, 起動していた qmail-local の数が1つ減った ことが分かる. 3 行目の「msg 1417777 to local」で, ローカル配送が成功したことが 分かる. (このメッセージは Jun 4 01:27:11 の「msg 1417777 to local rotty-epnetfan@ep.sci.hokudai.ac.jp」以来無かった) ・ 溜まっているメッセージの量の確認 - メッセージ全体のサイズを調べる # du -sh /var/qmail/queue/mess 4.1M /var/qmail/queue/mess (かなり減った) - メッセージの数を調べる # ls /var/qmail/queue/mess/*/* |wc 93 93 3024 (かなり減った) ・ 作業の完了 実際にローカルにメールを送る等してメールが配送されることを確認. 確認が終ったら作業終了. トラブルカルテを書いて Web に上げると 共に, epcore-ml に詳細をメール. ■ 今後の長期的対応 1. 放っておいて, また起きたら対処 2. メールサーバ管理者が時たまプロセスを見る (非現実的) 3. mail2news.pl を改良し, inews がハングしたら (または news サーバと 通信できなかったら) mail2news.pl を終了し, それに関わっていた qmail-local も停止できるようにする. ■ 参考資料 1. qmail-send(8) の concurrencylocal の部分 - http://man.qmail.jp/jman8/qmail-send.html 2. mail2news のインストール - http://www.ep.sci.hokudai.ac.jp/~epmail/y2004/dvlop/mail2news.html 3. qmail-send(8), qmail-lspawn(8), qmail-local(8) - http://man.qmail.jp/jman8/qmail-send.html - http://man.qmail.jp/jman8/qmail-lspawn.html - http://man.qmail.jp/jman8/qmail-local.html 4. 書籍『qmail メールサーバの構築』 (epnetfan 書棚にあり) Richard Blum, 2002: qmail メールサーバの構築. 株式会社アスキー, pp625. 5. セカンダリメールサーバの構築, ・セカンダリメールサーバとしての働き - http://www.ep.sci.hokudai.ac.jp/~epmail/y2004/dvlop/www.html#secondary ■ おまけ ・ 配送できていた最期の瞬間を示すログ - 2 行目に注目っ!! Jun 4 01:27:11 grey qmail: 1086280031.757197 status: local 9/10 remote 3/20 Jun 4 01:27:11 grey qmail: 1086280031.757219 starting delivery 2083931: msg 1417777 to local rotty-epnetfan@ep.sci.hokudai.ac.jp Jun 4 01:27:11 grey qmail: 1086280031.757238 status: local 10/10 remote 3/20 Jun 4 01:27:11 grey qmail: 1086280031.853733 delivery 2083924: success: 202.238.82.24_accepted_m essage./Remote_host_said:_250_Ok:_queued_as_2C0163181D/ Jun 4 01:27:11 grey qmail: 1086280031.853798 status: local 10/10 remote 2/20 Jun 4 01:27:11 grey qmail: 1086280031.853817 end msg 1417776 Jun 4 01:27:12 grey qmail: 1086280032.085061 delivery 2083926: success: 210.130.0.181_accepted_m essage./Remote_host_said:_250_Ok:_queued_as_2D41231774/ Jun 4 01:27:12 grey qmail: 1086280032.085107 status: local 10/10 remote 1/20 Jun 4 01:27:12 grey qmail: 1086280032.085126 end msg 1417780 ・ qmail-local を強制停止させた痕跡 # grep qmail-local_crashed /var/log/mail.log Jun 4 13:54:09 grey qmail: 1086324849.719683 delivery 1914980: deferral: qmail-local_crashed./ Jun 4 13:54:16 grey qmail: 1086324856.410043 delivery 1916599: deferral: qmail-local_crashed./ Jun 4 13:54:28 grey qmail: 1086324868.769395 delivery 1919712: deferral: qmail-local_crashed./ Jun 4 13:54:34 grey qmail: 1086324874.974330 delivery 1920071: deferral: qmail-local_crashed./ Jun 4 13:54:42 grey qmail: 1086324882.585626 delivery 1923201: deferral: qmail-local_crashed./ Jun 4 13:54:48 grey qmail: 1086324888.765474 delivery 2073318: deferral: qmail-local_crashed./ Jun 4 13:54:57 grey qmail: 1086324897.551703 delivery 2076776: deferral: qmail-local_crashed./ Jun 4 13:55:05 grey qmail: 1086324905.344822 delivery 2078978: deferral: qmail-local_crashed./ Jun 4 13:55:10 grey qmail: 1086324910.393668 delivery 2082092: deferral: qmail-local_crashed./ Jun 4 13:55:20 grey qmail: 1086324920.539243 delivery 2083931: deferral: qmail-local_crashed./