エンジニアですよ!

頑張れ俺くん、巨匠と呼ばれるその日まで

stackprof の wall mode で rails のプロファイルをとろうとしたら mysql の接続エラーがたくさん出てホストが mysql にブロックされてしまう話

起きたこととしては

  • stackprofrack-stackprofで使って rails アプリのプロファイルを取ろうとした
    • stackprof は wall mode で動いてる
  • すると、Host 'x.x.x.x' is blocked because of many connection errors が発生した
  • 起動後しばらくは正常に動いているが、しばらくするとエラーが連続して発生してしまうようで mysql サーバにブロックされアプリが動かなくなる。

原因は

  • stackprof は profile を取るために setitimer で定期的にシグナルを送る
  • wall モードの場合、 setitimerITIMER_REAL で動くので、実時間で定期的にシグナルを送る。
  • libmysql は mysql に接続後 poll でデータを待ち受ける。
  • poll で待っている間にシグナルを受け取ると、 pollEINTR で失敗して connection を切ろうとする。
  • ここで、サーバが既に Server Greeting を送っているのに切断されてしまうと、サーバとしては接続が不正に中断されたとしてエラーだと判断する。
    • (このあたりの詳細はよくわかってない。)
  • mysql には max_connect_errors という値があり、それを超える回数連続で接続が失敗するとそのホストをブロックする。
  • ってことで連続で失敗してブロックされてしまうってことみたいだった。

原因はわかったものの、世の中の人は stackprof で rails アプリケーションのプロファイリングをしているのにこういうことで困ってないということはなにかが間違っているような気もするし、mysqllocalhost だとブロックされることはないとか、普通は mysqlskip-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 の間は時間が進まないのでシグナルが送られることがなく、問題が起きないのだろう。きっと。

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 を返す。これはなんでなのかよくわからなかった。

f:id:totem_3:20190107212554p:plain

どう解決すべきなのか?

本当はクライアント側のもう少し早いところで 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 STATUSAborted_connects でも監視しておけばいいでしょう。

時系列

ここからは調べた履歴。行き当たりばったりで調べて時間を費やしたので自戒

activerecord-refresh_connection を使っているので、しばらくは rack middleware を新たに差し込んだことで切断のタイミングとかがおかしくなってるのでは??みたいな謎な想像をして、 ActiveRecord::ConnectionAdapters::RefreshConnectionManagementRack::StackProf順番を入れ替えたりしてた。もちろん無駄。

ローカルで再現しない、と思ってたのでデバッグは難しかった。(実際には問題は起きていた。先述の通りローカルだと mysqllocalhost で接続しているので接続がブロックされないので、まぁその点は再現しない)

このときは、接続はできてデータの取得もできているけど、切断がうまくいかなくて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 とかわかってないのが露呈する。

ぐぐってると偶然ヒントになったのはこの記事

Haskellからmysqlを実行する - 椿の日記

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_waitpoll で、 EINTR によってエラーになっているということを発見する。

なるほどシグナル受け取ると poll が失敗するのね〜と。

あとは RST が起きるのがわかってないが、諦めた。

メモ