Help us understand the problem. What is going on with this article?

keystoneとmysqlのコネクションが時々切れるバグについて(Juno)

More than 3 years have passed since last update.

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のタイムアウト」:60秒

らしい、つまり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'のタイムアウト」:8時間

ソケットを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') "

上記の2つが分かったところで大体エラーの正体がつかめてきた。
なんでこういうことが起きたか

まず、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. 解決策

解決策は下記の2つ

  1. oslo.db 1.0.2では、チェック用SQLの発行タイミングが変更されており、トランザクションを明示的に使用していないときでもチェック用SQLを発行しコネクションの使用確認を行ってくれるようになった。つまりoslo.db 1.0.2を使用すれば解決する(debパッケージはないので、自前でpackagingが必要)

  2. keystoneはkiloリリースで、すべてのsqlをトランザクションを用いて発行するため回避することが可能になる

こんなバグがJunoまで放置されているのだから、OpenStackは最高だ。

Why not register and get more from Qiita?
  1. We will deliver articles that match you
    By following users and tags, you can catch up information on technical fields that you are interested in as a whole
  2. you can read useful information later efficiently
    By "stocking" the articles you like, you can search right away
Comments
No comments
Sign up for free and join this conversation.
If you already have a Qiita account
Why do not you register as a user and use Qiita more conveniently?
You need to log in to use this function. Qiita can be used more conveniently after logging in.
You seem to be reading articles frequently this month. Qiita can be used more conveniently after logging in.
  1. We will deliver articles that match you
    By following users and tags, you can catch up information on technical fields that you are interested in as a whole
  2. you can read useful information later efficiently
    By "stocking" the articles you like, you can search right away
ユーザーは見つかりませんでした