モーグルとカバとパウダーの日記

モーグルやカバ(EXカービング)山スキー(BC)などがメインの日記でした。今は仕事のコンピュータ系のネタが主になっています。以前はスパム対策関連が多かったのですが最近はディープラーニング関連が多めです。

taRgrey/Starpitなどtarpittingでプロセス数が異常に増加する問題について

(追記)

解決しました。
問題は、(スパマーの切断処理が甘いため)古いバージョンのsleepパッチを使っている時だけ、smtpdのプロセスがタイムアウトするまで終了できないためでした。
sleepパッチが新しいバージョン(具体的にはsmtpdのstatusコードを指定するようにしたもの)であればこの問題は起きません。
ただ400秒のピークは、スパマーが切断をしていない(たぶんバグで切断がうまくいってない)ため、ここは解決できません。


まだ対策方法ができてないんで状況だけ。


taRgrey/Starpit(Selective tarpitting)で運用しているメールサーバで、smtpdプロセス数が通常の3〜4倍以上に増えるという状況が起こっています。
しかし、netstatで調べてみると約60%〜80%のプロセスはESTABLISHEDではなくTIME_WAIT(lsofで見るとLISTENしてる)になっており、どうやら切断待ちになっているプロセスが多量に出来ている、ということがわかりました。


そこで、postfixのログからセッション毎の接続時間を集計するスクリプトを書いて、セッション当りの接続時間数を見てみたところ、5月半ばあたりから600秒強(つまり10分)の接続をしているものが出てきて、現在は全メール中の30%弱を占めるまでになっています。
(ちなみに80秒で切ってくるスパムは18%程に低下しています。)
そして、10分もの接続を30%弱のメールが行うため、それらスパムによるsmtpdの時間占有率はなんと80%弱にも達していました。


ちなみにこのスパムは、sleepパッチのログにより10秒で諦めて帰っているのがわかりました。
なのですが、このスパムが諦めて帰る時にFINのACKを返してくれないため、こちら側のsmtpdはみーんなTCPのセッション終了待ちに入ってしまい、切れるまでに10分かかっているのではないかと推測。


ただ、自分が書いたsleepパッチ当ててる環境なので、sleepパッチが悪さしてうまくACKを取れないでいる、という可能性もある?かな?いやー、無いと思うんだが…という感じなんで、その辺をちゃんと確証とってから、対策を考えていきたいと思います。(3度自分を疑ってからスパマーを疑え :)


TIME_WAITでぐぐると、理由は違うけども、WebやDB系でも結構同じようなことで困ることが多いみたいですね。
なにかうまい対処法があれば教えてください。


赤が切断されるまでの時間。青がsmtpdの時間占有率。緑がセッション数の占有率。
600秒超のあたりに大きなピークがあるのがわかる。80秒超のあたりと、60秒のあたりにもtarpitで落とされた分のピークができている。400秒弱のところにもなんかできてきてるんだがなんだこれ?


(追記)

  • 600秒強のピークは、600秒+lost connectionまでの10秒
  • 400秒弱のピークは、300秒+tarpit時間の85秒

という感じでした。


HELOが逆引き名か引けないときはIPそのままであること、Envelope from/to が同一であること、という特徴から見て、実は同じbotから出されているのだけど、なんらかの理由でlost connectionが検知できた場合と、できなかった場合とでわかれている、ような気がします。


さらに不思議なのは600秒のものが、10秒でlost connectionしているにもかかわらず、宛先(RCPT TO)を受け取っていることです。
その場合は本来だと、pipeliningのログが出るように設計しているはずなのですが、そうならずにRCPT TOを送ってきています。
ということは、切断されてからRCPT TOのパケットが届いている?という謎状況になっちゃうんですが…
もしかするとTCPのパケットが無茶な順番で届いているとか、あるのかなあと。
こっちはソケットが切れてることを検知してるんだけども、ソケット断は行われているにもかかわらず、その後にACK送らずにRCPT TOのパケットがやってきてるとか??ソケット断なのにデータ受け取るとかあるんだろうか。

RCPT TO受け取ってからtarpitしてるんだから、出せるのは当たり前だわ。
そうじゃなくて、400秒のやつがlost connectionもpipeliningもしてないってところが変。単にスパム送信部分のバグのような気がする。
sleepパッチ使わないで試してみると現象が発生しない可能性あると思うので、試してみたいと思います。


ちなみに、400秒のものも600秒の10秒でコネクション切るものも同一のスパムっぽい気がしました。
どちらも遅延ですぐに送信を諦めるのですが、諦める場合の切断の処理が甘いこと、HELO等のクセが似てること、400秒のものと600秒のものが出始めた時期や増加率が一致すること、などからです。