起きたこととしては
- stackprofをrack-stackprofで使って rails アプリのプロファイルを取ろうとした
- stackprof は wall mode で動いてる
- すると、Host 'x.x.x.x' is blocked because of many connection errors が発生した
- 起動後しばらくは正常に動いているが、しばらくするとエラーが連続して発生してしまうようで mysql サーバにブロックされアプリが動かなくなる。
原因は
- stackprof は profile を取るために
setitimer
で定期的にシグナルを送る - wall モードの場合、
setitimer
がITIMER_REAL
で動くので、実時間で定期的にシグナルを送る。 - libmysql は mysql に接続後
poll
でデータを待ち受ける。 poll
で待っている間にシグナルを受け取ると、poll
はEINTR
で失敗して connection を切ろうとする。- ここで、サーバが既に Server Greeting を送っているのに切断されてしまうと、サーバとしては接続が不正に中断されたとしてエラーだと判断する。
- (このあたりの詳細はよくわかってない。)
- mysql には max_connect_errors という値があり、それを超える回数連続で接続が失敗するとそのホストをブロックする。
- ってことで連続で失敗してブロックされてしまうってことみたいだった。
原因はわかったものの、世の中の人は stackprof で rails アプリケーションのプロファイリングをしているのにこういうことで困ってないということはなにかが間違っているような気もするし、mysql が localhost だとブロックされることはないとか、普通は mysql で skip-name-resolve
を設定していて max_connect_errors
は関係なくなるので気付かないとかそういう話なのかもしれない。(会社でもオンプレのときは skip-name-resolve
は設定していたような気がする)
それぞれもう少し詳しく
stackprof
今回はじめて中身見た。 setitimer
もはじめて知った。プロファイラってこうやってやるんだな〜という。
setitimer
して定期的にシグナルを受け取って処理することで時間を測る。
計測モードにはいくつか種類があるが、README を見ると
four sampling modes are supported:
:wall (using ITIMER_REAL and SIGALRM)
:cpu (using ITIMER_PROF and SIGPROF) [default mode]
ということで、問題の wall モードでは ITIMER_REAL
が使われている。 ITIMER_PROF
だと poll
の間は時間が進まないのでシグナルが送られることがなく、問題が起きないのだろう。きっと。
- Man page of GETITIMER
- stackprof/stackprof.c at fd6b83295b92f49bc4ba76049cfbc9cb28bf0079 · tmm1/stackprof · GitHub
mysql2
問題の Mysql2::Client.new
が実際に何をやってるかというと、initialize
の最後で connect
している
この connect
メソッドは native extension の方で定義されている。実際には rb_mysql_connect
実際に接続しているのはここで、nogvl_connect
というメソッド。
こいつが libmysql の mysql_real_connect を呼んで接続する。
クライアント側が接続失敗に気付かないのは、この rb_mysql_connect
の中で、エラーが EINTR
であればリトライしているから。↓この部分。
mysql2/client.c at 3b9a26708fa86aba23763626331eb317ed457cc1 · brianmario/mysql2 · GitHub
libmysql
バージョンは 5.7.24。(そういえば、地味に cmake のときに boost が見つからないっていう問題があり解決できなかったなぁ。メッセージに従って -DDDOWNLOAD_BOOST=1 したんだけど)
いろいろ見たけど、 poll
しているのは vio/viosocket.c の vio_io_wait
の中 786 行目から。print 入れまくってここでエラーが出ているのにたどり着いた。
switch ((ret= poll(&pfd, 1, timeout))) { case -1: /* On error, -1 is returned. */ break; case 0: /* Set errno to indicate a timeout error. (This is not compiled in on WIN32.) */ errno= SOCKET_ETIMEDOUT; break; default: /* Ensure that the requested I/O event has completed. */ DBUG_ASSERT(pfd.revents & revents); break; }
poll
Man page of POLL のエラーのところを見ると
EINTR 要求されたイベントのどれかが起こる前にシグナルが発生した。 signal(7) 参照。
エラーの原因はこいつです。多分
RSTが起きるのはなぜか
tcpdump の結果はこういう感じで、ハンドシェイク直後にクライアントが FIN を送っていて、サーバは Greeting を送っており、その後クライアントは RST を返す。これはなんでなのかよくわからなかった。
どう解決すべきなのか?
本当はクライアント側のもう少し早いところで EINTR
のリトライをすればいいのでは?という気がする。けどまぁものによるだろうから仕方ないんだろうなぁ。
libmysql の mysql 8 のソースコードを見ると、この部分には ppoll
が使われるようになっていて、シグナルがマスクできるようになっている。
しかし、それを設定できるのはサーバ側だけで、クライアント側からは設定できない。残念。ここを設定できるようにすればいいよね。
実際に、 5.7 のソースコードで ppoll
に切り替えて SIGALRM
をマスクするようにしたところ問題は発生しなくなった。プロファイルの結果には微妙に影響があるだろうけど、エラーが出るよりは全然良い。
ただ、さすがに libmysql にパッチを当てるのは厳しいのでクライアント側で対応するのは難しい。
とするとサーバ側でなんとかするしかない。
で、↓を見た。 max_connect_errors
回連続した接続失敗でホストをブロックするのをやめよう。ほんとにエラーでなくするだけだけど………
MySQL 5.6のインストール後にチューニングすべき項目 | Yakst
max_connect_errors
というのは skip-name-resolve
を有効にしていると無効になるようだ。skip-name-resolve
は名前解決を利用しない限り設定することが推奨される項目であり、この度エラーが出ていた環境では設定していなかったが経験上本番環境でも設定されていた。
つまり, max_connect_errors
回を超える接続失敗によって接続を拒否するなんてしなくてもいいんだ。そもそも mysql を外部に晒すなんてことはないわけで、攻撃を受けるとしたら内部から。内部に侵入されているのにこれで検知できるような攻撃されるってことはないだろう…多分。ってことでセキュリティ的にはあまり懸念はないはず。
あとはこういう微妙なケースで実は接続エラーが発生しているということに気付かないという可能性はあるが、めったにあることではないので、 SHOW GLOBAL STATUS
の Aborted_connects
でも監視しておけばいいでしょう。
時系列
ここからは調べた履歴。行き当たりばったりで調べて時間を費やしたので自戒
activerecord-refresh_connection を使っているので、しばらくは rack middleware を新たに差し込んだことで切断のタイミングとかがおかしくなってるのでは??みたいな謎な想像をして、 ActiveRecord::ConnectionAdapters::RefreshConnectionManagement
とRack::StackProf
順番を入れ替えたりしてた。もちろん無駄。
ローカルで再現しない、と思ってたのでデバッグは難しかった。(実際には問題は起きていた。先述の通りローカルだと mysql に localhost で接続しているので接続がブロックされないので、まぁその点は再現しない)
このときは、接続はできてデータの取得もできているけど、切断がうまくいかなくてmysqlサーバにエラーだと判定されているんだと思っていた。なぜなら起動後普通に動いているのに、しばらくするとホストが block されるから。 (https://twitter.com/takhirata/status/1081069642334928896 )
ローカルでも VM を立ててつなげると再現することに気づいてから少しデバッグが楽になった。ログになんか出てるのでは?とふと思って mysql のログを見ると、
[Note] Got an error writing communication packets
や
[Note] Got an error reading communication packets
が出ていることにやっと気づいた。このときローカルのmysqlのログを見て、ローカルでも起きてる事に気づいた。ログは見よう。
いつエラーが起きてるのか全然わからないし、デバッガで止めてしまうとあまり再現しなくなるので現在時刻を出力する print をいたるところに入れて、エラーのタイムスタンプと比較してどのへんで起きてるんだ〜とか探ったりしてた。
ここまでは rails アプリでリロードしまくって再現してたけど、 ↑を頑張った結果、 Mysql2::Client.new(config) で問題が発生しているということがわかり、再現するのにこのくらい↓のコードでよくなったので更にデバッグが楽になった。
config = {...} StackProf.run do 10.times do c = Mysql2::Client.new(config) c.close end end
しかしエラーが起きたかどうかはプロセス内部からどう観測すればいいかこのときはよくわかってなかったので、 mysql のログの最後の一行を実行前と後で比較して変化してたらエラーが起きたと判断するみたいなことをやってた。これで mysql2 とか stackprof の bisect 的なこともしたけど、バージョンは関係ないことがわかる。
これで設定変えるのが楽になったので、 StackProfの設定をいろいろといじってみて mode: :cpu
だと大丈夫だとか、 interval
を長くすると起きにくい、短くすると起きやすいとかいうことに気付く。で、ようやく stackprof がプロファイルを取るって何してんのかよくわかってないなーということに気付き、そこを調べる。
それでようやくシグナルにたどり着く。
なんかSIGALRMが悪そうだな〜と思い始めるが、signalはstackprofがハンドルしているはずだし、何をどう調べればいいのか皆目検討がつかなかった。 system call とかわかってないのが露呈する。
ぐぐってると偶然ヒントになったのはこの記事
RTS.hscのコメントによれば、どうやらmysqlclientの関数はこれらのシグナルの割り込み後の復帰処理が上手く出来てないらしく、これらのシグナルを無効にして実行しないとならない場合があるようです。
ほほう。
でここから libmysql に目が向き始める。
libmysql のデバッグ方法が全然わからなかった。とりあえずデバッグ有効にしてビルドして LD_PRELOAD で .so 差し替えてデバッグした。 gdb 使ってたけどやっぱり break すると再現あんまりしないしどこで問題が起きてるのか結局よくわからないので、結局 debug print を libmysql に足しまくって調べた。 print debug 最強。
しかし、もともと DBUG_PRINT
とかがたくさん仕込まれていたのでそれを有効にするだけで良かったはずなんだけど、これをどうやって有効にするのか結局最後までわからなかった…(ので自分で fprintf を入れてビルドし直しを繰り返した)
これで CLI_MYSQL_REAL_CONNECT
から追いに追いに追った結果、 vio/viosocket.c の vio_io_wait
の poll
で、 EINTR
によってエラーになっているということを発見する。
なるほどシグナル受け取ると poll
が失敗するのね〜と。
あとは RST が起きるのがわかってないが、諦めた。
メモ
- PSI Interface ってのはなんなのか
- wireshark expert infomation