tl;dr

Rails 5.0.5 で octopus 0.9.0 を使うと MySQL のコネクションがしばらく放置していると切れるようになり、再接続もできなくなります。
原因は rails 5 で query_cache の実装が諸々変わっているが、octopus がそれに追従できていないことの模様。
リクエストが来たタイミングでコネクションを明示的に貼り直せば一旦回避はできる。

はじめに

弊社ではゲームのアプリケーションサーバーの開発フレームワークとしてRuby on Railsを使用しています。
また、DB のシャーディングに octopus を使っています。

Rails 4 から Rails 5 にバージョンアップして開発を進めていると、
「開発環境にしばらくアクセスしないままでいると、次にアクセスした際に500エラーが返却されてしまう」ということが起きてしまいました。

朝になるとほぼ確実に、開発環境のサーバーがエラーを返すようになっているので、
アプリケーションサーバーを再起動して回るという超イケてないことになってしまいました。

赤笛の僕ですが、この謎を解くべくアビス(Rails)の深層に挑んで見ることにしました。¹

起きていた問題

まずログを見てみると、
Mysql2::Error: MySQL server has gone away, Mysql2::Error: MySQL client is not connected というようなエラーが出ていることを確認できました。
どうやら MySQL とのコネクションが切れてしまっているようです。

必ずしばらくアクセスしない場合のとき(主に明朝)に上記エラーが出ていたので、
おそらく wait_timeout が原因でコネクションが MySQL 側で切られてしまうことがこのエラーの原因だと予想できました。

なぜ Rails 4 から 5 に上げた際にこの問題が起こったのか？

一方バージョンアップする前にはこのような問題は起こっていませんでした。
おそらく今までも wait_timeout による接続切れは起こっていたはずですが、なぜバージョンアップした後に起きてしまったのだろうか？
その謎を解くためにアビスの深層へと潜ることを決めました。

Rails の再接続の仕組み

Railsではコントローラのアクションが呼ばれる前にミドルウェア層が実行されるが、その中で query_cache の初期化が行われます。
通常、その中で connection の生存チェックもしくは再接続をおこないます。
(クエリキャッシュについてはこちらを参考 Rails のクエリキャッシュの仕組みを調べた - takatoshiono's blog)

おそらくこのあたりの処理でうまく再接続が行かなくなったようです。
実際に挙動を追ってみたほうが早そうなのでまずはうまく行っていた Rails 4.2.9, Octopus 0.8.6 で追ってみました。

Rails 4.2.9、 octopus 0.8.6 の場合

ミドルウェアの処理の中でquery cache のクリアが呼ばれる。
https://github.com/rails/rails/blob/79c9f2e/activerecord/lib/active_record/query_cache.rb#L34 (79c9f2e は rails v4.2.9)

connection.eanble_query_cache! これを octopus が hijack
https://github.com/thiagopradi/octopus/blob/a138b93/lib/octopus/model.rb#L114 (a138b93 は octopus v0.8.6)

本来のenable_query_cache! ではなく octopus の enable_query_cache! が呼ばれる。
https://github.com/thiagopradi/octopus/blob/a138b93/lib/octopus/proxy.rb#L315

ここで with_each_helathy_shard で全てのshardに対してsafe_connection が呼ばれる。
https://github.com/thiagopradi/octopus/blob/a138b93/lib/octopus/proxy.rb#L226

safe_connectionでは、connectio_pool の connection が呼ばれるが、これは Rails の connection が呼ばれて、
https://github.com/rails/rails/blob/79c9f2e/activerecord/lib/active_record/connection_adapters/abstract/connection_pool.rb#L263

中身で checkout_verify が呼ばれ、最終的に接続できてなかったら recoonect に至る。
https://github.com/rails/rails/blob/79c9f2e/activerecord/lib/active_record/connection_adapters/abstract/connection_pool.rb#L351
https://github.com/rails/rails/blob/79c9f2e/activerecord/lib/active_record/connection_adapters/abstract/connection_pool.rb#L454
https://github.com/rails/rails/blob/79c9f2e/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb#L340

と、ちゃんとコネクションの検証を行い、場合によっては再接続を試みているのがわかりました。
それでは Rails 5 の場合を追ってみましょう。

Rails 5.0.5、 Octopus 0.9.0 の場合

以下のように query_cache_enabled が connection_pool に対して呼ばれるようになっています。
これをoctopus は hijack できずに、 octopus 周りの処理が呼ばれません。
https://github.com/rails/rails/blob/450889d/activerecord/lib/active_record/query_cache.rb#L30

と、ミドルウェアの処理段階ではOctopus は何もしないようになっていることがわかりました。世知辛いですね。

暫定対策

コントローラーのアクション前にコネクションを生存確認して、再接続するというのがもともと期待していた動作でした。
なのでこれを明示的に書いてあげることで対策はできそうです。

というわけで ApplicationController の before_action にてすべての shard に対してコネクションの生存確認と再接続を行うようにしてあげました。
今回の件はこれで解決することができました。

class ApplicationController < ActionController::Base
  before_action :verify_all_shards_connection!

  def verify_all_shards_connection!
    ActiveRecord::Base.connection.shard_names.each do |shard|
      Octopus.using(shard) do
        if ActiveRecord::Base.connection_pool.connected? && !ActiveRecord::Base.connection_pool.connection.active?
          ActiveRecord::Base.connection_pool.connection.reconnect!
        end
      end
    end
  end
end

所感

Rails、octopus の挙動を深く終えたのは勉強になりました。
まだ他のoctopusのバージョンなどを試せていないので、このバグは治っているかもしれないですが、
octopus は Rails 側のインターフェースが変わるとそれに追従していかないといけなくて結構つらそうな印象です。
他の gem を検討しても良いかもしれません。

その他

rails 5 でも一つの connection の再接続がなされるが、これは Migration::CheckPending によって行われるものである。
- https://github.com/rails/rails/blob/450889d/activerecord/lib/active_record/migration.rb#L559
- https://github.com/thiagopradi/octopus/blob/1383d18/lib/octopus/proxy.rb#L303 で一つだけ connection が選ばれる

参考

メイド・イン・アビス面白い ↩

Rails 5 で Octopus を使用する際の問題点と解決策