loveruby.net に時々メールが届かないことがある。 過去何度も調べてきたのだが結局原因はよくわからずじまい。 開通からもう半年にもなろうというのに……。これでは なんのために苦労して自宅サーバを立てているのかわからない。 おそまきながら解決に向けてもう一度調査してみることにした。
TCP コネクションはつながるけどそのあと通信が流れず、 タイムアウトになる。このときファイアウォールに ill-cmd:Rece というログが大量に残る。届く届かないがかなりメチャクチャ なのも特徴。
とある人が親切にも発生条件を調べてくれたのだが、どうも SMTP で PIPELINING がオンになってるとダメらしい。んで 某 postfix ML で 「それは broken Path MTU Discovery が原因だろう。FAQ だ」 と言われたらしい。
そこでこれについて調べてみたが、これが問題になるのはどうやら メールを送るときらしい。つまり受け取るときがおかしい 家の問題とは違うような気がする。それでも手掛りが少ないので とにかく調べてみた。メモがわりに簡単にまとめる。
IP はパケット単位の配送を行う。そのパケットひとつの大きさが MTU (Max Transfer Unit)。単位はオクテット(バイト)。 この大きさは経路によって違うため、大きな MTU から小さな MTU に 移るときにパケットの分割が起こることがある。これは速度低下の 原因になるので、最初から相手までの最小 MTU で投げるのが望ましい。 この最小 MTU を検出するのが Path MTU Discovery だ。
ところが、このワザは DF (Don't Flagment) という ICMP コマンドを 利用するのだが、途中にひどいルータがあるとこの ICMP パケットを 無視して捨ててしまうことがある。そうすると送信側サーバはこの ICMP パケットをいつまでも待ちつづけてフリーズすることになる。
んで対策はどうするかというと、Path MTU Discovery をやると止まる わけだから、最初から Path MTU Discovery が起動しないように小さい パケットで投げることにすればよい。具体的には、ルータの WAN 側の MTU を小さくすればよいらしい。フレッツやめたりっくでは 1454 以下に なっていれば OK だ。
ところが、うちのルータの MTU は最初っから 1440 だったのだ。 てことは Path MTU Discovery がらみではない。また、この問題はプロトコルに 関係なく起こるはずであるが、HTTP では実際になにも問題が起こっていない。 だから家の問題は PMTU-D ではありえないと結論できた。
昔どっかの雑誌で 「smtp 開けるなら ident も開けておかないと変なエラーになることがある」 というのを読んだことがあったので、これを調べてみることにした。 適当に ident smtp とかでぐ〜ぐるしてみてわかったことは、 (1) ルータで ident を捨てていて (2) 相手が設定変な sendmail、だと sendmail が返ってこない ident の返事をずっと待ってしまい、止まる らしい。
相手のことはどうにもならないが、こっちで ident をただ捨てずに reject してやれば相手が待たなくなる(この二つは全然違う)ので、 ident を開けることにする。SUA で ident をサーバに向け、ファイア ウォールも 113 番ポートを開ける。
……変わらない……うがー！
いかにもなさそうであるが、ファイアウォールに ill-cmd と出ている 以上なんか悪いのかもしれない。最終手段登場だぁ！ Ruby で smtpd を 書いて全部トレースしてみることにした。うーん、SMTP ライブラリ 書いたことあってよかったなあー。
書けた。所要時間 10 分くらい。
require 'socket'
def smtpd
srv = TCPServer.new( (ARGV[0] || 25).to_i )
@sock = srv.accept
output "220 mail.loveruby.net ESMTP\r\n"
waitfor 'EHLO', "250-ok\r\n"
output "250-SIZE\r\n"
### output "250-PIPELINING\r\n"
output "250 HELP\r\n"
waitfor 'MAIL FROM', "250 ok\r\n"
waitfor 'RCPT TO', "250 ok\r\n"
waitfor 'DATA', "354 go ahead\r\n"
until (s = readline()) == ".\r\n" do
;
end
output "250 ok\r\n"
waitfor 'QUIT', "221 mail.loveruby.net\r\n"
@sock.close
end
def waitfor( str, okmsg )
re = Regexp.new('\A' + str, 'i')
until re === (s = readline()) do
if /\AQUIT/i === s then
output "221 mail.loveruby.net\r\n"
@sock.close
exit
end
output "502 not implemented\r\n"
end
output okmsg
end
def readline
s = @sock.gets
@log.puts s.dump
s
end
def output( str )
@sock.print str
@log.puts str.dump
end
File.open('logfile', 'w') {|f|
@log = f
smtpd()
}
はぁぁー、なんていいかげんなんだ！！ まあいいや。telnet でテストして、稼働〜。
……をい！ 問題ねえよ！ メール届くよ！ なんでだよ！ ぬうう。 というところで、以前のメールで「PIPELINING だとだめ」というのが あったので、smtpd() のコメントアウトしてあるところを戻して ためしてみる……動かない。ファイアウォールでひっかかる。うむう。 なんでだ？ ログも見てみたが、いたって普通の SMTP セッションに しか見えない。
相手がおかしくないとすると、こっちの smtpd だろうか？ telnet で 確かめてみたがやはり特に変なところはない。あとはファイアウォール しかない。とりあえずファイアウォールを切ってみた。すると何事もなく メールが届く。
ここで整理してみると、問題が起こるのは
のときだ。この条件だとなにがいかんのか。こっからは本当に推測だけども、 うちのルータにはフルインスペクションファイアウォールってのが入ってる。 これはプロトコルの内部にまで入ってコマンドの流れをチェックし、危険 そうなものを全部弾く。もしかしてこのファイアウォールが PIPELINING SMTP に対応してないのではないか。PIPELINING の場合、複数の SMTP コマンドが ひとつのパケットにつめこまれてくるので、それをちゃんと把握できていない 場合、コマンドの流れが変に見えるはずだ。
そう考えると、ill-cmd:Rece の Rece は本文の Received: ヘッダでは ないかと思える。また、さらにログを見てみたところ、ill-cmd: 3 D と いうのを発見できた。これは Date: ヘッダの一部ではないか？ よおし、 かなり信憑性がたかくなってきたぜ。
つまり、対策としてはファイアウォールを切るか、ルータを捨てるか、 うちの smtpd に PIPELINING を使わせなければよい。ルータを捨てるのは、 かなり高かったのでちょっとイヤ。ファイアウォールを切るのも、その 高いぶんがまるで意味なくなるので悔しい。残る選択肢は PIPELINING を 使わせないことだ。
どうすれば PIPELIING をオフにできるか。安易な順に書こう。
ちなみに家のサーバは Debian。つーことは smtpd はデフォで exim である。 ぐ〜ぐるしてみたところ、PIPELINING をオフにするオプションはない らしいことが判明した。鬱。
もうちょっと探してみると、どうも postfix には no_pipelining_without_auth という「いかにも」なオプションがあるようだ。うーん、しかし MTU を OS デフォルトじゃないやつに変えるのはちょっと面倒くさいな。
んで、結局ココにやってくるのね。ソース書き換え。オープンソースまんせー。 とりあえず exim のバージョンを調べてみる。
$ exim --version $ exim -version $ exim -v $ exim --help $ exim -help $ exim -h
全滅。さいさき悪いなあ。
strings /usr/sbin/exim | less
はっけんしました、はっけーん。3.12 らしいです。3.12 のソースを exim のサイト からダウンロードしてきて、PIPELINING を 発行してるところを探す。PIPELINING で grep すると smtp_in.c に そのものズバリがみつかった。これを #if 0 で抹殺して終わり。 たいしたことはなかったな。
……うそつきましたごめんなさい。コンパイルがすんごく面倒でした。 なんでいまどき Makefile 手動書き換えなんですか。いやセキュリティ 確保するためってのはわかるけどさ、もうちょっとなんとかならないの？ しかもログファイルの位置指定するの忘れるとログ取らないし…… qmail もそうだったけど、smtpd はどれもコンパイル面倒なのね。
テスト。ちゃんと送れた。はあ……よかった……
そうだ、最後にルータをつるしあげ。ZyXel の ZyWALL10 っていう ルータです。気をつけましょう。
前回 CVS にチェックインしてから変更したファイル名を調べる ワンライナー。
cvs diff --brief | grep ^Index | cut -d\ -f2
TMail 用に stringio.rb とそのテストを書く。楽しい。 でもやっぱこれは標準ライブラリに欲しいなあ。
今日中にだしたかったが無理そうだ。今日はもう夕飯たべて 明日の早朝に出そう。
早くも 0.10.0 からソースコード変えまくり。一番変わったのは fileutils.rb を使わなくなったとこと、loader.rb が消滅した ところか。
突如おもいたって rdtool の簡単インストールパッケージを作りだす。 シェルスクリプトでサクッとパック、コンパイル、テスト。
その途中、Ruby の load が $LOAD_PATH を見ることをいまさら知った。 なんてこった。ずっとこうだったっけ？ ……うーむ、1.4.6 は見てるな。 やっぱりずっとそうらしい。ショック。
あれ？ rmi2html って動かないみたいだなー。
マジやめてくれよ。対応するの大変なんだよ。
最近、ruby のコンパイルが妙に遅い。どうも GC が頻発しているようだ。 ここんとこ GC 生起のアルゴリズムが変わったせいだろうか？
思いたって CVS サーバを設置した。cvs.loveruby.net だ。 アカウント anonymous パスワード anonymous で行ける。 これでパッケージをリリースする期間を短くできるに違いない。 これは、長いあいだやろうと思いつつも面倒でやってなかったんだけど、 思いきってやってみたら意外と簡単だった。設定とか、ロクにないのね。
1/2 に書いたルータ (ZyWALL10) の問題をメーカーに問い合わせて みたところ、やっぱりファイアウォールのバグだとわかった。バグ 自体はダメダメだが、はっきりバグとわかったのでとりあえず安心だ。 んで、最新のファームウェア (V350WA1j0) だとなおってるらしい。
そんなわけですこしサーバを止めて、ルータのファームウェアを アップデートした。いまのところまったく問題なく動いている。
ついでに掃除もしたら凄まじい量のほこりが積もっていた。
UPS はつないてあるが、実はまだソフトを入れてないのであった。 つまり停電になってもしばらくは持ちこたえるが、バッテリが 切れてしまうと結局いきなり切れるのである。これは困る。ちゃんと 入れよう。
UPS はオムロンの BX50XF というやつである。Linux 対応のソフトが ついてるってんで買ったんだが、CD の中を見てみると RedHat とか TarboLinux といったディレクトリが並んでいる。Debian はやっぱりない。 とても困る。しかたないので適当な RPM をみつくろって alien で .tar.gz に変換し、中を見てみることにした。
シェルスクリプトがインターフェイスらしいので、まずそれを解読 してみる。どうやら poweragent と upsconfig いうコマンドが核 らしいので、それを ldd やstrings にかけてみる。うう、明らかに 共有ライブラリが足りねえ。これは動かないだろうなあ。
いろいろやったが結局だめだったので、あきらめる。はあ……
結局添付ソフトが動かなかった UPS であるが、その後 Debian の 本を買ったら genpower というソフトのことが書いてあった。汎用 UPS 監視ソフトらしい。BX50XF 向けの設定については 単独のページ に記す。
ようやくサーバまわりはイイ感じになってきた。ていうか、 この程度は半年前サーバをたてたときにやっとくべきであった。
TMail のロードが遅い、とるびきちさんに言われたり、どこかの日記 にも書いてあったので気になって調べてみた。すると、本当に遅い。 以前は家では遅くなかったのに、すごく遅くなっている。そのときは 「0.01 秒で終わる」と書いてあるのに、いまは 0.20 秒かかる。 こりゃいくらなんでも遅すぎだろう。というわけで調査してみた。
まず、ruby -rtmail -e0 の時間を各バージョンで計測。
1.7 0.24 1.6.6 0.18 1.6.5 0.18 1.6.4 0.11 1.6.3 0.11
ふむ。1.6.5 と 1.7 で二段階遅くなってるな。なんとなく こういう遅くなりかたは GC くさい。GC をオフにしてみよう。
1.7 0.10 1.6.6 0.08 1.6.4 0.07
うむ。やっぱり GC が大幅に遅くなっているようだ。 しかし、GC 以外の部分も遅くなっているのでついでにそっちも 計測してみよう。TMail のファイルを結合したものを ruby -c するのにかかる時間を計測。
1.7 0.08 1.6.6 0.06 1.6.4 0.05
ruby -e0 にかかる時間は 0.02 秒なので、まとめるとこうなる。
StartUp Compile Evaluate GC Total 1.7 0.02 0.06 0.02 0.10 0.20 1.6.6 0.02 0.04 0.02 0.07 0.15 1.6.4 0.02 0.03 0.02 0.01 0.08
(Evaluate は module_eval のコンパイル分も含む)。 ここから、遅くなっているのはコンパイルと GC で、特に GC の 増加分が大きいことがわかる。GC の発生回数を調べてみると、 1.6.4 が 3 回、1.6.6 が 19 回、1.7 が 20 回となった。つまり GC 一回が遅いのではなく GC 起動の回数が多いのだと考えられる。
一方、無駄な式をたくさん入れた大きなファイルを作って ruby -c してみると以下のようになった。
1000 2000 3000 4000 5000 (行)
1.7 0.08 0.12 0.18 0.24 0.27
1.7nogc 0.05 0.08 0.12 0.15 0.18
GC time 0.03 0.04 0.06 0.09 0.09
1.6.4 0.05 0.14 0.23 0.35 0.56
1.6.4nogc 0.03 0.06 0.09 0.10 0.12
GC time 0.02 0.08 0.14 0.25 0.44
ん？ おかしいな。今度は 1.7 の GC が妙に速い。と思ったら、 こっちのほうが GC の回数が少ないからだった。5000 行でも 6 回しか起きていない。なんで TMail は GC が多いんだろう？
……わかった。require したあと必ず GC するからだ！ そういうことかあ〜。調べてみると、ruby.c 1.43 からだ。 ちゃんとログも残ってるな。うーんしかし、これはあんまし うれしくないなあ。
ごはんを炊いた。おかずがない。冷蔵庫の中に納豆が見つかった。 賞味期限を見る。去年だ。食べたら死ぬだろうか？ 死ぬだろうか？ 体で試してみることにする。
まつもとさんからパッチが！ なんかすげーあっさり出てくるもん なのね。やっぱり 100 の予想より 1 のバックトレースなのか。 ああ……。自分がいやになってきた。
ココアを作ろうと思った。冷蔵庫の中から牛乳を出す。ふと 賞味期限を見る。おとといだ。
……ま、これは問題ない。
Ruby 新年会 いいなあ。関東もやりたいなあ。次は花見だろうか。
「好きなデザインパターン」ですか……。Tosh さんナイス。 ちなみにおれは Strategy が好き。
ところで、サマリの「まつもとさん、あおきさん、るびきちさんの実像」 というのはなんなのだろう。なぜにわたくしめがまつもとさんの次に！？
ちなみに、Ruby Hacking Guide 最新は別の場所 に移転しております。いちおう増えてます。いちおう。もっと たくさん書きたいんだけどね、ちょっと時間がね。それと、 いままでずっと CVS 最新にひっついてきたけど、1.6.6 とかに 特化してネチネチ書いたほうがいいかなあとか思ってるのもあるし。 そうするとソースインクルードが自動化できるし、ドキュメントと 連動したクロスリファレンスも提供できるようになる。
Ruby Hacking Guide のために、Ruby のソースコードをリンクとかいろいろつけて HTML 化しようと思い、スクリプトを書きはじめる。
が、その途中で出来合いのツールを使ったほうが賢いな、 と思いなおし global を試してみることにする。
ふーん……。使いかたは簡単だね。とりあえず出力するだけなら ソースのディレクトリでこうすれば OK。
$ gtags $ htags
しかし生成された HTML が FONT 直指定だったりして気にくわない。 CSS 使うようにしたいな。FONT 直指定はコンフィグファイルで 変更できるようだ。しかし css の指定ができないので htags を 直接書き換えることにする。……最近こういうの多いな。
$ file `which htags` /usr/local/bin/htags: perl command text
Perl じゃん。ま、出力変えるくらいならなんとかなるだろう。 適当に grep で HTML ヘッダを出力してるらしいところを探し、 CSS へのリンクをハードコーディングしておいた。
あー、でも関数の a name が番号だな。別のドキュメントから リンクするには名前のほうがいいんだよなあ。やっぱり自作しよう かなあ。関数をハイパーリンクにするくらいならもう実装できてるし。
Copyright (c) 2000-2002 Minero Aoki
<aamine@loveruby.net>
This site is link free.