1. はじめに
JunoのOpenStackを構築していて、keystoneがdatabaseとの接続にたまに失敗するバグに遭遇し、そのバグについて調べたらいろいろ勉強になったので記事にしておきます。
今更、Junoかよっていうツッコミはあるかと思いますが、物好きな人がいるかもしれないので、書いておきます。
2. 遭遇したエラー
keystoneがたまに、下記のようなエラーを吐く。
DB接続に失敗しているようですね。
[:error] [pid 25779:tid 13913232] 25779 TRACE keystone.common.wsgi DBConnectionError: (OperationalError) (2006, 'MySQL server has gone away') 'SELECT user.id AS user_id, user.name AS user_name, user.domain_id AS user_domain_id, user.password AS user_password, user.enabled AS user_enabled, user.extra AS user_extra, user.default_project_id AS user_default_project_id \\nFROM user \\nWHERE user.name = %s AND user.domain_id = %s' ('demo', 'default')
3. 原因の切り分け
3.1 MySQLは動いているのか？
→正常に動いている
3.1.1 MySQLのプロセスを見てみる（mysql -u -e "show full processlist"）
+-----+-------------+---------------------------------+---------+---------+-----+
| Id | User | Host | db | Command |Time |
+-----+-------------+---------------------------------+---------+---------+-----+
| 974 | keystone | host:46963 | keystone | Sleep | 1 |
| 978 | keystone | host:46967 | keystone | Sleep | 3 |
| 979 | keystone | host:46968 | keystone | Sleep | 2 |
| 980 | keystone | host:46969 | keystone | Sleep | 1 |
Command:Sleepってなんだ？
「Command:Sleep」： MySQLクライアントは、SQL発行の高速化のために一度確立したTCPセッションを使い回すことができる。その使い回される確立したTCPセッションのプロセスは、Sleepの状態になっている。
また、timeカラムの値はCommandの状態になってからの経過時間を示す。つまり、最後にクエリが発行されてからの経過時間を示す
3.2. Networkの問題なのか？
3.2.1 MySQLサーバ側の状態を調べてみる（netstat -an ）
Proto Recv-Q Send-Q Local Address Foreign Address (state)
tcp4 0 0 192.168.100.11.3306 192.168.100.10.5432 ESTABLISHED
tcp4 0 0 192.168.100.11.3306 192.168.100.10.5433 FIN_WAIT2
tcp4 0 0 192.168.100.11.3306 192.168.100.10.5434 FIN_WAIT2
なんだか普段あまり見ないステータス「FIN_WAIT2」が見える。
「FIN_WAIT2」: 対向ノードにFINパケットを送って、ACKパケットを受け取り、対向ノードからのFINパケットを待っている状態
「FIN_WAIT2のタイムアウト」：６０秒
らしい、つまりkeystone側からFINパケットが来ていない状態になっているTCPセッションがあることが分かった。続いて、keystone側も見てみる
3.2.2 KeyStone側の状態を調べてみる（netstat -an ）
Proto Recv-Q Send-Q Local Address Foreign Address (state)
tcp4 0 0 192.168.100.10.5432 192.168.100.11.3306 ESTABLISHED
tcp4 0 0 192.168.100.10.5433 192.168.100.11.3306 CLOSE_WAIT
tcp4 0 0 192.168.100.10.5434 192.168.100.11.3306 CLOSE_WAIT
こちらでは、「CLOSE_WAIT」のステータスになっている。
「CLOSE_WAIT」：対向ノードからFINパケットを受け取り、ACKパケットを送出し、自端末のTCPソケットのCLOSEシステムコールを待っている状態
「'CLOSE_WAIT'のタイムアウト」：８時間
ソケットをcloseするとFINパケットが対向ノードに飛ぶみたい、とするとkeystone側がcloseの処理が呼ばれていないみたい。
4. まとめ（考察）
切り分けをしているうちに下記のことがわかった
-
MariaDB(Mysql)側が、wait_timeoutの時間、無応答なTCPセッションはFIN応答(server→client)を出し、クライアントはACK応答(client→server)のみを返す。このとき互いの状態はserver[FIN_WAIT2]、client[CLOSE_WAIT]になる。この状態になると、このTCPセッションはもう使えない。
-
クライアントのコネクションプールの中に、すでにセッションが切れているスレッドが混じっており（上記が理由）、SQLの発行の際、運悪くそのスレッドに当たると下記のようなエラーが吐かれ、SQLが失敗する。
"DBConnectionError: (OperationalError) (2006, 'MySQL server has gone away') "
上記の２つが分かったところで大体エラーの正体がつかめてきた。
なんでこういうことが起きたか
まず、OpenStackに限らずこういうことを回避するために、コネクションプールを使う際は、コネクションプールにあるスレッドは常にTCPセッションが確立されている状況でないといけない。
それの実現方法は、たくさんあるが、いくつか例をあげると
- コネクションプールのコネクションがタイムアウトしないように、定期的にsqlを発行する
- mysql側のwait_timeout時間を増やし、コネクションがタイムアウトしづらくする
- mysql側のwait_timeout時間を迎える前にクライアント側が、TCPセッションをクローズしコネクションプールから外す
- mysql側から、FINパケットをもらったらきちんとFIN,ACKパケットを返しセッションをクローズし、コネクションプールから外す
ただ、OpenStackではどうしているかというと、コネクションプールのTCPセッションが常に確立されている状態に保っている訳ではなく
- sql発行前に、コネクションが切れているか確認するためのsql発行し、切れていたら新しくコネクションを張って、SQLを発行する
ということを行っている。
ただ、各コンポーネント(keystoneとかnova)がsql発行前にチェック用sql（select 1;）を発行している訳ではなく、oslo.dbという共通コンポーネントがこれを実現してくれている。
なので、通常は各コンポーネントは、コネクションプールとか意識しないで良い。
5. なんでこういうことが起きたか（結論）
しかし、oslo.dbがチェック用SQLを発行してくれるタイミングは、トランザクションを開始する前にコーディングされておりトランザクションを使用しないSQLの発行前にはコネクションの使用確認SQLを発行してくれないらしい。
keystonelはトランザクションを使用せずautocommitモードでsqlを発行するため(junoリリース版まで）、コネクションの使用確認を行わずにSQLを発行してしまう。よって"DBConnectionError: (OperationalError) (2006, 'MySQL server has gone away') "というエラーが出てしまう。
6. 解決策
解決策は下記の２つ
-
oslo.db 1.0.2では、チェック用SQLの発行タイミングが変更されており、トランザクションを明示的に使用していないときでもチェック用SQLを発行しコネクションの使用確認を行ってくれるようになった。つまりoslo.db 1.0.2を使用すれば解決する(debパッケージはないので、自前でpackagingが必要)
-
keystoneはkiloリリースで、すべてのsqlをトランザクションを用いて発行するため回避することが可能になる
こんなバグがJunoまで放置されているのだから、OpenStackは最高だ。